From b22f99a3aff38d3f713d36474d962f6350b51625 Mon Sep 17 00:00:00 2001 From: Justin Chen Date: Thu, 29 Oct 2026 20:58:38 -0700 Subject: [PATCH 1/4] chat: persist agent-host reasoning timing Preserve producer-owned timing across live updates, reconnection, and saved chat history so fallback thinking headers retain their elapsed time. Record Copilot reasoning against durable assistant-message IDs without timing replay or inventing missing historical durations. Sync the optional protocol fields from microsoft/agent-host-protocol commit f9d401d7. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../agentHost/common/sessionDataService.ts | 12 ++ .../common/state/protocol/.ahp-version | 2 +- .../state/protocol/channels-chat/actions.ts | 7 +- .../state/protocol/channels-chat/reducer.ts | 7 +- .../state/protocol/channels-chat/state.ts | 4 + .../node/compatibleSessionDatabase.ts | 8 + .../node/copilot/copilotAgentSession.ts | 41 ++++- .../node/copilot/copilotReasoningTiming.ts | 81 ++++++++++ .../node/copilot/copilotSubagentTracking.ts | 4 + .../node/copilot/mapSessionEvents.ts | 2 + .../agentHost/node/sessionDatabase.ts | 38 ++++- .../test/common/sessionTestHelpers.ts | 11 +- src/vs/platform/agentHost/test/node/README.md | 8 + .../test/node/copilotAgentSession.test.ts | 45 +++++- .../test/node/copilotReasoningTiming.test.ts | 143 ++++++++++++++++++ .../test/node/sessionDatabase.test.ts | 42 ++++- .../agentHost/agentHostSessionHandler.ts | 18 ++- .../importLocalConversationToAgentSession.ts | 9 +- .../agentHost/stateToProgressAdapter.ts | 19 ++- .../chatThinkingContentPart.ts | 24 ++- .../contrib/chat/common/model/chatModel.ts | 27 +++- .../agentHostChatContribution.test.ts | 39 ++++- ...ortLocalConversationToAgentSession.test.ts | 15 ++ .../stateToProgressAdapter.test.ts | 30 ++++ .../chatThinkingContentPart.test.ts | 50 +++--- .../chat/test/common/model/chatModel.test.ts | 48 ++++++ 26 files changed, 678 insertions(+), 56 deletions(-) create mode 100644 src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts create mode 100644 src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts diff --git a/src/vs/platform/agentHost/common/sessionDataService.ts b/src/vs/platform/agentHost/common/sessionDataService.ts index 4b545506fd779..9467867a21bcb 100644 --- a/src/vs/platform/agentHost/common/sessionDataService.ts +++ b/src/vs/platform/agentHost/common/sessionDataService.ts @@ -98,6 +98,12 @@ export interface IReviewedFileRecord { // ---- Session database --------------------------------------------------- +/** A producer-measured reasoning interval, keyed by its durable provider response id. */ +export interface IReasoningTiming { + readonly startedAt: string; + readonly duration: number; +} + /** A host-persisted turn that is absent from the provider transcript. */ export interface IPersistedTurnRecord { /** Whether this is host-local or a provider turn that failed before persistence. */ @@ -266,6 +272,12 @@ export interface ISessionDatabase extends IDisposable { */ getTurnUsages(): Promise>; + /** Records completed reasoning timing with the owning turn's pruning lifecycle. */ + setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise; + + /** Reads recorded reasoning timings after all previously submitted writes. */ + getReasoningTimings(): Promise>; + /** * Persists the JSON-serialized delegation metadata for an agent-authored turn. * Idempotent — last writer wins per turn. diff --git a/src/vs/platform/agentHost/common/state/protocol/.ahp-version b/src/vs/platform/agentHost/common/state/protocol/.ahp-version index d51683b6ada87..a9fb20f1335e9 100644 --- a/src/vs/platform/agentHost/common/state/protocol/.ahp-version +++ b/src/vs/platform/agentHost/common/state/protocol/.ahp-version @@ -1 +1 @@ -5872a476 +f9d401d7 diff --git a/src/vs/platform/agentHost/common/state/protocol/channels-chat/actions.ts b/src/vs/platform/agentHost/common/state/protocol/channels-chat/actions.ts index db20e7d2b67d3..ac6007997bc90 100644 --- a/src/vs/platform/agentHost/common/state/protocol/channels-chat/actions.ts +++ b/src/vs/platform/agentHost/common/state/protocol/channels-chat/actions.ts @@ -678,7 +678,8 @@ export interface ChatUsageAction { * Reasoning/thinking text from the model, appended to a specific reasoning response part. * * The server MUST first emit a `chat/responsePart` to create the target - * reasoning part, then use this action to append text to it. + * reasoning part, then use this action to append text or record its timing. + * An empty `content` updates only the supplied timing fields. * * @category Chat Actions * @version 1 @@ -691,6 +692,10 @@ export interface ChatReasoningAction { partId: string; /** Reasoning text chunk */ content: string; + /** Producer-recorded ISO 8601 start of the reasoning interval; omitted to preserve the existing value. */ + startedAt?: string; + /** Final elapsed reasoning time in non-negative integer milliseconds, measured by the producer's clock; omitted to preserve the existing value. Zero is a recorded duration, not unknown. */ + duration?: number; /** * Additional provider-specific metadata for this action. * diff --git a/src/vs/platform/agentHost/common/state/protocol/channels-chat/reducer.ts b/src/vs/platform/agentHost/common/state/protocol/channels-chat/reducer.ts index 5a4fd6d79b516..806cb16f6e4c5 100644 --- a/src/vs/platform/agentHost/common/state/protocol/channels-chat/reducer.ts +++ b/src/vs/platform/agentHost/common/state/protocol/channels-chat/reducer.ts @@ -763,7 +763,12 @@ export function chatReducer(state: ChatState, action: ChatAction, log?: (msg: st case ActionType.ChatReasoning: return updateResponsePart(state, action.turnId, action.partId, part => { if (part.kind === ResponsePartKind.Reasoning) { - return { ...part, content: part.content + action.content }; + return { + ...part, + content: part.content + action.content, + ...(action.startedAt !== undefined ? { startedAt: action.startedAt } : {}), + ...(action.duration !== undefined ? { duration: action.duration } : {}), + }; } return part; }); diff --git a/src/vs/platform/agentHost/common/state/protocol/channels-chat/state.ts b/src/vs/platform/agentHost/common/state/protocol/channels-chat/state.ts index 1dbe18f14fcb9..a87b8e03be435 100644 --- a/src/vs/platform/agentHost/common/state/protocol/channels-chat/state.ts +++ b/src/vs/platform/agentHost/common/state/protocol/channels-chat/state.ts @@ -1131,6 +1131,10 @@ export interface ReasoningResponsePart { id: string; /** Accumulated reasoning text */ content: string; + /** Producer-recorded ISO 8601 start of this reasoning interval; absent when unknown. */ + startedAt?: string; + /** Final elapsed reasoning time in non-negative integer milliseconds, measured by the producer's clock; absent while unfinished or unknown. Clients MUST NOT derive it from their own clock. */ + duration?: number; } /** diff --git a/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts b/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts index a0682deec0116..39333d9edcb26 100644 --- a/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts +++ b/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts @@ -72,6 +72,14 @@ export class CompatibleSessionDatabase implements ISessionDatabase { return result; } + async setReasoningTiming(...args: Parameters): ReturnType { + return this.raw.setReasoningTiming(...args); + } + + async getReasoningTimings(): ReturnType { + return this.raw.getReasoningTimings(); + } + async getTurnDelegations(...[]: Parameters): ReturnType { const result = await this.raw.getTurnDelegations(); return new Map([...result].map(([key, value]) => [key, this.identity.metadata('agentHost.turnDelegation', value, 'runtime')!])); diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 5cecd7b49c163..19f0635d83743 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -57,6 +57,7 @@ import { createUnknownAgentHostClientTelemetryContext, type IAgentHostClientTele import { measureAgentProviderOperation } from '../../common/agentHostProviderTiming.js'; import { type AgentCanvasDefinitionSnapshot, AgentSession, type IAgentChatOwnerRef, type IAgentExtensionInfo, type IAgentManagedPluginRetryEntry, COPILOT_CLI_AGENT_PROVIDER_ID, AgentSignal, AgentWorkingDirectoryChangedError, AuthenticateParams, IMcpNotification, subagentChatTitle, type AgentCanvasExtensionSource, type AgentExtensionStatus, type AgentSubagentTaskModelSource, type AgentTurnProviderCallState, type IAgentCanvasCloseRequest, type IAgentCanvasOpenRequest, type IAgentPendingMessageSender, type IAgentPermissionResponseContext, type IAgentTelemetryContext, type IAgentToolPendingConfirmationSignal, type IAgentTurnDiagnosticSnapshot, type IAgentTurnTokenUsage } from '../../common/agent.js'; import { isReasoningEffortLevel } from '../../common/reasoningEffort.js'; +import { CopilotReasoningTiming } from './copilotReasoningTiming.js'; import { agentModelConfigurationMetaKey, IAgentRuntimeModelConfiguration, readAgentRuntimeModelConfiguration } from '../../common/meta/agentModelConfigurationMeta.js'; import { agentModelConfigurationReportKey, type IAgentModelConfigurationReport } from '../../common/agentModelConfiguration.js'; import { createCopilotModelConfigurationReport } from './copilotManagedModelConfiguration.js'; @@ -1110,6 +1111,17 @@ export class CopilotAgentSession extends Disposable { private readonly _chatChannelUri: URI; /** Fixed persistence scope for this chat; never re-derived from the mutable routing channel. Config reads/writes go through {@link _configTarget} instead — peer chats share that scope but have distinct storage. */ private readonly _storageUri: URI; + private readonly _reasoningTiming = this._register(new CopilotReasoningTiming( + (action, parentToolCallId) => this._emitProgress({ kind: 'action', resource: this._chatChannelUri, action, parentToolCallId }), + (turnId, responseId, timing) => { + if (!turnId) { + this._logService.trace(`[Copilot:${this.sessionId}] Cannot persist reasoning timing without an owning turn`); + return; + } + void this._withDatabase(db => db.setReasoningTiming(turnId, responseId, timing)).catch(error => + this._logService.error(`[Copilot:${this.sessionId}] Failed to persist reasoning timing`, error)); + }, + )); get chatChannelUri(): URI { return this._chatChannelUri; @@ -2375,6 +2387,11 @@ export class CopilotAgentSession extends Disposable { if (action.type === ActionType.ChatUsage && !parentToolCallId && this._launchPlan.localModelProvider) { this._lastRootUsage = { turnId: action.turnId, usage: action.usage }; } + if (action.type === ActionType.ChatDelta || action.type === ActionType.ChatToolCallStart || action.type === ActionType.ChatInputRequested + || (action.type === ActionType.ChatResponsePart && action.part.kind !== ResponsePartKind.Reasoning) + || action.type === ActionType.ChatTurnComplete || action.type === ActionType.ChatTurnCancelled || action.type === ActionType.ChatError) { + this._reasoningTiming.finish(parentToolCallId); + } this._emitProgress({ kind: 'action', resource: isChatAction(action) ? this._chatChannelUri : this._ownerSessionUri, @@ -3359,11 +3376,14 @@ export class CopilotAgentSession extends Disposable { } private _clearSubagentResponseParts(parentToolCallId: string): void { + this._reasoningTiming.finish(parentToolCallId); + this._reasoningTiming.clear(parentToolCallId); this._subagentResponsePartState.markdownPartIds.delete(parentToolCallId); this._subagentResponsePartState.reasoningPartIds.delete(parentToolCallId); } private _beginToolCallRound(parentToolCallId: string | undefined): void { + this._reasoningTiming.finish(parentToolCallId); const scope = parentToolCallId ?? ''; const state = this._getResponsePartState(parentToolCallId); state?.markdownPartIds.delete(scope); @@ -3391,6 +3411,7 @@ export class CopilotAgentSession extends Disposable { } private _startTurn(turnId: string, senderClientId: string | undefined, clientContext = createUnknownAgentHostClientTelemetryContext(AgentHostClientType.Unknown), providerInitiated = false): void { + this._reasoningTiming.clear(undefined); this._clearActivity(); this._setManagedPluginActivity(undefined); this._detectInterruptedTurnOnRestore = false; @@ -3818,7 +3839,7 @@ export class CopilotAgentSession extends Disposable { } /** Emits a reasoning delta, similar to {@link _emitMarkdownDelta} but for reasoning parts. */ - private _emitReasoningDelta(content: string, parentToolCallId?: string): void { + private _emitReasoningDelta(content: string, reasoningId: string, parentToolCallId?: string): void { if (this._shouldDropLateRootTurnEvent('assistant.reasoning_delta')) { return; } @@ -3828,17 +3849,24 @@ export class CopilotAgentSession extends Disposable { return; } const reasoningScope = parentToolCallId ?? ''; + const timingTurnId = parentToolCallId ? this._subagents.getRootTurnId(parentToolCallId) ?? this._turnId : this._turnId; let partId = state.reasoningPartIds.get(reasoningScope); + if (partId !== this._reasoningTiming.activePartId(timingTurnId, reasoningId, parentToolCallId)) { + partId = undefined; + } if (!partId) { partId = generateUuid(); state.reasoningPartIds.set(reasoningScope, partId); + const startedAt = this._reasoningTiming.start(timingTurnId, reasoningId, partId, parentToolCallId); + this._reasoningTiming.append(content, parentToolCallId); this._emitAction({ type: ActionType.ChatResponsePart, turnId: this._turnId, - part: { kind: ResponsePartKind.Reasoning, id: partId, content }, + part: { kind: ResponsePartKind.Reasoning, id: partId, content, startedAt }, }, parentToolCallId); return; } + this._reasoningTiming.append(content, parentToolCallId); this._emitAction({ type: ActionType.ChatReasoning, turnId: this._turnId, @@ -9248,6 +9276,12 @@ export class CopilotAgentSession extends Disposable { if (this._shouldDropLateRootTurnEvent('assistant.message')) { return; } + if (isLastMessageChunk) { + const recorded = this._reasoningTiming.completeMessage(e.id, e.data.reasoningText, contentParentToolCallId); + if (!recorded && e.data.reasoningText) { + this._logService.trace(`[Copilot:${this.sessionId}] No complete observed reasoning interval for assistant message ${e.id}`); + } + } const markdownScope = contentParentToolCallId ?? ''; const state = this._getResponsePartState(contentParentToolCallId); const isEmptyFinalAnswer = isLastMessageChunk && e.data.phase === 'final_answer' && !e.data.content && !e.data.toolRequests?.length; @@ -10832,7 +10866,7 @@ export class CopilotAgentSession extends Disposable { if (this._shouldDropUnmappedSubagentEvent(e, 'assistant.reasoning_delta')) { return; } - this._emitReasoningDelta(e.data.deltaContent, this._parentToolCallIdForSubagentEvent(e)); + this._emitReasoningDelta(e.data.deltaContent, e.data.reasoningId, this._parentToolCallIdForSubagentEvent(e)); })); // Sync the AHP session config when the SDK's `currentMode` changes @@ -12336,6 +12370,7 @@ export class CopilotAgentSession extends Disposable { store.add(wrapper.onReasoning(e => { this._logService.trace(`[Copilot:${sessionId}] Reasoning: ${e.data.content.length} chars`); + this._reasoningTiming.finish(this._parentToolCallIdForSubagentEvent(e), e.data.reasoningId); })); store.add(wrapper.onTurnEnd(e => { diff --git a/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts b/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts new file mode 100644 index 0000000000000..87e03726d12b0 --- /dev/null +++ b/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts @@ -0,0 +1,81 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import { Disposable } from '../../../../base/common/lifecycle.js'; +import { StopWatch } from '../../../../base/common/stopwatch.js'; +import type { IReasoningTiming } from '../../common/sessionDataService.js'; +import { ActionType, type ChatReasoningAction } from '../../common/state/sessionActions.js'; + +interface IReasoningInterval { + readonly turnId: string; + readonly startedAt: string; + readonly content: string[]; + duration: number; + active?: { readonly reasoningId: string; readonly partId: string; readonly startedAt: string; readonly clock: StopWatch }; +} + +/** Measures live fragments and associates their total with the SDK's durable assistant message. */ +export class CopilotReasoningTiming extends Disposable { + private readonly _intervals = new Map(); + + constructor( + private readonly _emit: (action: ChatReasoningAction, parentToolCallId: string | undefined) => void, + private readonly _persist: (turnId: string, responseId: string, timing: IReasoningTiming) => void, + ) { + super(); + } + + activePartId(turnId: string, reasoningId: string, parentToolCallId: string | undefined): string | undefined { + const interval = this._intervals.get(parentToolCallId); + return interval?.turnId === turnId && interval.active?.reasoningId === reasoningId ? interval.active.partId : undefined; + } + + start(turnId: string, reasoningId: string, partId: string, parentToolCallId: string | undefined): string { + this.finish(parentToolCallId); + const startedAt = new Date().toISOString(); + if (this._intervals.get(parentToolCallId)?.turnId !== turnId) { + this._intervals.set(parentToolCallId, { turnId, startedAt, content: [], duration: 0 }); + } + const interval = this._intervals.get(parentToolCallId)!; + interval.active = { reasoningId, partId, startedAt, clock: StopWatch.create() }; + return startedAt; + } + + append(content: string, parentToolCallId: string | undefined): void { + this._intervals.get(parentToolCallId)?.content.push(content); + } + + finish(parentToolCallId: string | undefined, reasoningId?: string): void { + const interval = this._intervals.get(parentToolCallId); + if (!interval?.active || (reasoningId !== undefined && reasoningId !== interval.active.reasoningId)) { + return; + } + const { partId, startedAt, clock } = interval.active; + const duration = Math.max(0, Math.round(clock.elapsed())); + interval.active = undefined; + interval.duration += duration; + this._emit({ type: ActionType.ChatReasoning, turnId: interval.turnId, partId, content: '', startedAt, duration }, parentToolCallId); + } + + completeMessage(responseId: string, reasoningText: string | undefined, parentToolCallId: string | undefined): boolean { + this.finish(parentToolCallId); + const interval = this._intervals.get(parentToolCallId); + const recorded = interval !== undefined && !!reasoningText && interval.content.join('') === reasoningText; + if (recorded) { + this._persist(interval.turnId, responseId, { startedAt: interval.startedAt, duration: interval.duration }); + } + this.clear(parentToolCallId); + return recorded; + } + + clear(parentToolCallId: string | undefined): void { + this._intervals.delete(parentToolCallId); + } + + override dispose(): void { + this._intervals.clear(); + super.dispose(); + } +} diff --git a/src/vs/platform/agentHost/node/copilot/copilotSubagentTracking.ts b/src/vs/platform/agentHost/node/copilot/copilotSubagentTracking.ts index 918cd32d29d34..37c1919f56c04 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotSubagentTracking.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotSubagentTracking.ts @@ -109,6 +109,10 @@ export class CopilotSubagentTracking extends Disposable { return this._children.get(toolCallId)?.rootTurnId !== undefined; } + getRootTurnId(toolCallId: string): string | undefined { + return this._children.get(toolCallId)?.rootTurnId; + } + belongsToRootTurn(toolCallId: string, rootTurnId: string): boolean { return this._children.get(toolCallId)?.rootTurnId === rootTurnId; } diff --git a/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts b/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts index 475e2c3466afe..e393724a867ae 100644 --- a/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts +++ b/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts @@ -481,6 +481,7 @@ export async function mapSessionEvents( const workingDirectory = options?.workingDirectory; let currentModel = options?.model; let currentAgent = options?.agent; + const reasoningTimings = await db?.getReasoningTimings(); // First pass: collect tool-arg info and identify edit tool calls so we // can batch-load their stored file edits before the second pass needs // them at `tool.execution_complete` time. We also build the @@ -936,6 +937,7 @@ export async function mapSessionEvents( kind: ResponsePartKind.Reasoning, id: generateUuid(), content: reasoningText, + ...reasoningTimings?.get(e.id), }); } if (content) { diff --git a/src/vs/platform/agentHost/node/sessionDatabase.ts b/src/vs/platform/agentHost/node/sessionDatabase.ts index bd8a3c5f93888..b288bbb12a6c0 100644 --- a/src/vs/platform/agentHost/node/sessionDatabase.ts +++ b/src/vs/platform/agentHost/node/sessionDatabase.ts @@ -6,7 +6,7 @@ import * as fs from 'fs'; import { Sequencer, SequencerByKey } from '../../../base/common/async.js'; import type { Database, RunResult } from '@vscode/sqlite3'; -import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../common/sessionDataService.js'; +import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReasoningTiming, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../common/sessionDataService.js'; import { dirname } from '../../../base/common/path.js'; import { URI } from '../../../base/common/uri.js'; import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, type Message } from '../common/state/sessionState.js'; @@ -261,6 +261,15 @@ export const sessionDatabaseMigrations: readonly ISessionDatabaseMigration[] = [ PRIMARY KEY (tool_call_id, ordinal) )`, }, + { + version: 17, + sql: `CREATE TABLE IF NOT EXISTS reasoning_timing ( + response_id TEXT PRIMARY KEY NOT NULL, + turn_id TEXT NOT NULL REFERENCES turns(id) ON DELETE CASCADE, + started_at TEXT NOT NULL, + duration INTEGER NOT NULL CHECK(duration >= 0) + )`, + }, ]; // ---- Promise wrappers around callback-based @vscode/sqlite3 API ----------- @@ -764,6 +773,32 @@ export class SessionDatabase implements ISessionDatabase { }); } + setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise { + return this._mutate(async db => { + if (!Number.isFinite(Date.parse(timing.startedAt)) || !Number.isSafeInteger(timing.duration) || timing.duration < 0) { + throw new Error('Invalid reasoning timing'); + } + await dbRun(db, 'INSERT OR IGNORE INTO turns (id) VALUES (?)', [turnId]); + await dbRun(db, 'INSERT OR REPLACE INTO reasoning_timing (response_id, turn_id, started_at, duration) VALUES (?, ?, ?, ?)', + [responseId, turnId, timing.startedAt, timing.duration]); + }); + } + + async getReasoningTimings(): Promise> { + await this.whenIdle(); + const db = await this._ensureDb(); + const rows = await dbAll(db, 'SELECT response_id, started_at, duration FROM reasoning_timing', []); + const result = new Map(); + for (const row of rows) { + if (typeof row.response_id !== 'string' || typeof row.started_at !== 'string' || !Number.isFinite(Date.parse(row.started_at)) + || typeof row.duration !== 'number' || !Number.isSafeInteger(row.duration) || row.duration < 0) { + throw new Error('Invalid persisted reasoning timing'); + } + result.set(row.response_id, { startedAt: row.started_at, duration: row.duration }); + } + return result; + } + setTurnDelegation(turnId: string, delegation: string): Promise { return this._mutate(async db => { await dbRun(db, 'INSERT OR IGNORE INTO turns (id) VALUES (?)', [turnId]); @@ -1607,6 +1642,7 @@ export class SessionDatabase implements ISessionDatabase { // or the forked session would restore with no gauge and zero cost. for (const [oldId, newId] of mapping) { await dbRun(db, 'UPDATE turn_usage SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); + await dbRun(db, 'UPDATE reasoning_timing SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); await dbRun(db, 'UPDATE turn_delegation SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); await dbRun(db, 'UPDATE turn_workspace_transition SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); } diff --git a/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts b/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts index 223f2d4c111c2..8803d317f325e 100644 --- a/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts +++ b/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts @@ -9,7 +9,7 @@ import { URI } from '../../../../base/common/uri.js'; import { Emitter, Event } from '../../../../base/common/event.js'; import { constObservable } from '../../../../base/common/observable.js'; import type { IDetailedDiffResult, IDiffComputeService, IDiffCountResult, IDiffHunksResult } from '../../common/diffComputeService.js'; -import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionDataService, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../../common/sessionDataService.js'; +import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReasoningTiming, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionDataService, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../../common/sessionDataService.js'; import type { IAgentHostCheckpointService } from '../../common/agentHostCheckpointService.js'; import type { IAgentHostGitStateService } from '../../common/agentHostGitStateService.js'; import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, type ISessionGitHubState, type Message } from '../../common/state/sessionState.js'; @@ -49,6 +49,7 @@ export class TestSessionDatabase implements ISessionDatabase { private readonly _turns = new Set(); private readonly _persistedTurns = new Map(); private readonly _turnUsages = new Map(); + private readonly _reasoningTimings = new Map(); private readonly _turnDelegations = new Map(); private readonly _turnWorkspaceTransitions = new Map(); private readonly _turnEventIds = new Map(); @@ -362,6 +363,13 @@ export class TestSessionDatabase implements ISessionDatabase { async getTurnUsages(): Promise> { return new Map(this._turnUsages); } + async setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise { + this._turns.add(turnId); + this._reasoningTimings.set(responseId, timing); + } + + async getReasoningTimings(): Promise> { return new Map(this._reasoningTimings); } + async setTurnDelegation(turnId: string, delegation: string): Promise { this._turns.add(turnId); this._turnDelegations.set(turnId, delegation); @@ -440,6 +448,7 @@ export class TestSessionDatabase implements ISessionDatabase { async deleteAllTurns(): Promise { this.deleteAllTurnsCalls++; this._turns.clear(); + this._reasoningTimings.clear(); this._edits.length = 0; this._turnDelegations.clear(); this._turnWorkspaceTransitions.clear(); diff --git a/src/vs/platform/agentHost/test/node/README.md b/src/vs/platform/agentHost/test/node/README.md index 72eab13a6bb3f..1821c4d3cf357 100644 --- a/src/vs/platform/agentHost/test/node/README.md +++ b/src/vs/platform/agentHost/test/node/README.md @@ -12,6 +12,14 @@ Tests that launch a real provider process isolate its home, configuration, logs, The protocol and E2E folders contain their own running and authoring instructions. +## Reasoning timing + +AHP reasoning parts carry optional producer-owned `startedAt` and `duration` fields. Timing-only `chat/reasoning` updates finish a live interval before subsequent response content or the turn's terminal action. Clients retain those values across snapshots and history replay rather than measuring replay or comparing the host's clock with their own. + +Copilot measures streamed reasoning with a monotonic clock and stores its total against the durable assistant-message event id in the session database's `reasoning_timing` table. Split fragments contribute only their observed reasoning time; tool execution and gaps between fragments are excluded. Writes follow the owning turn through fork remapping and pruning. Restored provider responses without a complete recorded interval remain untimed; this does not retroactively estimate older sessions or add timing capture to other providers. + +`copilotReasoningTiming.test.ts` covers fragment measurement and a real database close/reopen followed by provider history reconstruction. `copilotAgentSession.test.ts`, `sessionDatabase.test.ts`, and the workbench chat adapter/model/thinking-content tests cover producer wiring, storage, reconnects, serialization, and the visible and accessible "Thought for 45s" label. + ## Mission Control session configuration The Mission Control listener publishes Copilot Host's `approvalMode` vocabulary (`manual`, `assisted`, `allow-all`) in place of VS Code's native `autoApprove` vocabulary (`default`, `assisted`, `autoApprove`). The independent `mode` property advertises `interactive`, `plan`, and `autopilot`. Local clients and persisted configuration keep the native representation; Mission Control requests, snapshots, action echoes, and reconnect replay use the wire representation. diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index fb179248e9eb0..841caa3ad4765 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -20,6 +20,7 @@ import { encodeBase64, VSBuffer } from '../../../../base/common/buffer.js'; import { Emitter, Event } from '../../../../base/common/event.js'; import { Disposable, DisposableStore } from '../../../../base/common/lifecycle.js'; import { Schemas } from '../../../../base/common/network.js'; +import { StopWatch } from '../../../../base/common/stopwatch.js'; import { join, sep } from '../../../../base/common/path.js'; import { hasKey } from '../../../../base/common/types.js'; import { URI } from '../../../../base/common/uri.js'; @@ -16693,12 +16694,13 @@ Use the attached image as context. } return { kind: action.part.kind, scope: signal.parentToolCallId ?? 'parent', content: action.part.content }; } - return action.type === ActionType.ChatReasoning + return action.type === ActionType.ChatReasoning && action.content ? { kind: 'delta', scope: signal.parentToolCallId ?? 'parent', content: action.content } : undefined; }).filter(update => update !== undefined); - assert.deepStrictEqual({ updates, parentReasoningParts: reasoningIds.size }, { + const timingScopes = signals.flatMap(signal => signal.kind === 'action' && signal.action.type === ActionType.ChatReasoning && signal.action.duration !== undefined ? [signal.parentToolCallId ?? 'parent'] : []); + assert.deepStrictEqual({ updates, parentReasoningParts: reasoningIds.size, timingScopes }, { updates: [ { kind: ResponsePartKind.Reasoning, scope: 'parent', content: 'Before notification' }, { kind: ResponsePartKind.Reasoning, scope: 'task-running', content: 'Child reasoning' }, @@ -16708,6 +16710,7 @@ Use the attached image as context. { kind: 'delta', scope: 'task-running', content: ' still running' }, ], parentReasoningParts: 2, + timingScopes: ['parent'], }); }); @@ -23666,12 +23669,49 @@ Use the attached image as context. }); }); + test('publishes and persists reasoning timing before the assistant answer', async () => { + const database = new TestSessionDatabase(); + const { session, mockSession, signals } = await createAgentSession(disposables, { sessionDatabase: database }); + const elapsed = stub(StopWatch.prototype, 'elapsed').returns(45_000); + try { + session.resetTurnState('host-turn'); + mockSession.fire('assistant.reasoning_delta', { reasoningId: 'sdk-reasoning', deltaContent: 'First' }); + mockSession.fire('assistant.reasoning_delta', { reasoningId: 'sdk-reasoning', deltaContent: ' thought' }); + mockSession.fire('assistant.message', { messageId: 'sdk-message', content: 'Done', reasoningText: 'First thought' }, { id: 'durable-response' }); + const actions = signals.flatMap(signal => signal.kind === 'action' ? [signal.action] : []); + const reasoning = actions.flatMap(action => action.type === ActionType.ChatResponsePart && action.part.kind === ResponsePartKind.Reasoning ? [action.part] : [])[0]; + const finalTiming = actions.flatMap(action => action.type === ActionType.ChatReasoning && action.duration !== undefined ? [action] : [])[0]; + const timingIndex = actions.indexOf(finalTiming); + const answerIndex = actions.findIndex(action => action.type === ActionType.ChatResponsePart && action.part.kind === ResponsePartKind.Markdown); + const recorded = await database.getReasoningTimings(); + + assert.deepStrictEqual({ + duration: finalTiming?.duration, + partIdMatches: finalTiming?.partId === reasoning?.id, + publishedBeforeAnswer: timingIndex >= 0 && timingIndex < answerIndex, + recorded: [...recorded.keys()], + recordedDuration: recorded.get('durable-response')?.duration, + startMatches: recorded.get('durable-response')?.startedAt === reasoning?.startedAt, + }, { + duration: 45_000, + partIdMatches: true, + publishedBeforeAnswer: true, + recorded: ['durable-response'], + recordedDuration: 45_000, + startMatches: true, + }); + } finally { + elapsed.restore(); + } + }); + test('reasoning delta after tool_start starts a new reasoning response part', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); session.resetTurnState('turn-1'); // First reasoning delta — allocates a fresh reasoning response part. mockSession.fire('assistant.reasoning_delta', { + reasoningId: 'reasoning-before-tool', deltaContent: 'thinking step 1', } as SessionEventPayload<'assistant.reasoning_delta'>['data']); @@ -23692,6 +23732,7 @@ Use the attached image as context. // renderer / state-tree would merge it into the pre-tool-call // block and the visual ordering would be wrong on restore. mockSession.fire('assistant.reasoning_delta', { + reasoningId: 'reasoning-after-tool', deltaContent: 'thinking step 2', } as SessionEventPayload<'assistant.reasoning_delta'>['data']); diff --git a/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts b/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts new file mode 100644 index 0000000000000..a0021f7fafe56 --- /dev/null +++ b/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts @@ -0,0 +1,143 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import assert from 'assert'; +import { promises as fs } from 'fs'; +import { tmpdir } from 'os'; +import sinon from 'sinon'; +import { join } from '../../../../base/common/path.js'; +import { StopWatch } from '../../../../base/common/stopwatch.js'; +import { URI } from '../../../../base/common/uri.js'; +import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../base/test/common/utils.js'; +import type { IReasoningTiming } from '../../common/sessionDataService.js'; +import { ActionType, type ChatReasoningAction } from '../../common/state/sessionActions.js'; +import { ResponsePartKind } from '../../common/state/sessionState.js'; +import { CopilotReasoningTiming } from '../../node/copilot/copilotReasoningTiming.js'; +import { mapSessionEvents } from '../../node/copilot/mapSessionEvents.js'; +import { SessionDatabase } from '../../node/sessionDatabase.js'; +import { toSessionEvents } from './copilotTestEvents.js'; + +suite('CopilotReasoningTiming', () => { + const store = ensureNoDisposablesAreLeakedInTestSuite(); + let elapsed = 0; + + setup(() => { + elapsed = 0; + sinon.useFakeTimers({ now: 1000, toFake: ['Date'] }); + sinon.stub(StopWatch.prototype, 'elapsed').callsFake(() => elapsed); + }); + + teardown(() => sinon.restore()); + + function createTiming() { + const actions: { action: ChatReasoningAction; parentToolCallId: string | undefined }[] = []; + const recorded: { turnId: string; responseId: string; timing: IReasoningTiming }[] = []; + const timing = store.add(new CopilotReasoningTiming( + (action, parentToolCallId) => actions.push({ action, parentToolCallId }), + (turnId, responseId, value) => recorded.push({ turnId, responseId, timing: value }), + )); + return { timing, actions, recorded }; + } + + test('records 45 seconds against the durable assistant message without a reasoning completion event', () => { + const { timing, actions, recorded } = createTiming(); + timing.start('turn', 'sdk-reasoning', 'part', undefined); + timing.append('Thinking', undefined); + elapsed = 45_000; + timing.completeMessage('assistant-event', 'Thinking', undefined); + timing.finish(undefined); + + assert.deepStrictEqual({ actions, recorded }, { + actions: [{ parentToolCallId: undefined, action: { type: ActionType.ChatReasoning, turnId: 'turn', partId: 'part', content: '', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 } }], + recorded: [{ turnId: 'turn', responseId: 'assistant-event', timing: { startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 } }], + }); + }); + + test('sums split reasoning fragments without including the gaps or timing another chat', () => { + const { timing, actions, recorded } = createTiming(); + timing.start('turn', 'reasoning-1', 'first', undefined); + timing.append('First', undefined); + timing.start('turn', 'child-reasoning', 'child', 'tool'); + timing.append('Child', 'tool'); + elapsed = 30_000; + timing.finish(undefined); + elapsed = 1500; + timing.completeMessage('child-message', 'Child', 'tool'); + timing.start('turn', 'reasoning-2', 'second', undefined); + timing.append(' second', undefined); + elapsed = 15_000; + timing.completeMessage('parent-message', 'First second', undefined); + + assert.deepStrictEqual({ + fragments: actions.map(({ action, parentToolCallId }) => ({ part: action.partId, duration: action.duration, parentToolCallId })), + totals: recorded.map(record => ({ response: record.responseId, duration: record.timing.duration })), + }, { + fragments: [ + { part: 'first', duration: 30_000, parentToolCallId: undefined }, + { part: 'child', duration: 1500, parentToolCallId: 'tool' }, + { part: 'second', duration: 15_000, parentToolCallId: undefined }, + ], + totals: [{ response: 'child-message', duration: 1500 }, { response: 'parent-message', duration: 45_000 }], + }); + }); + + test('preserves zero but does not invent timing for unobserved, mismatched, or interrupted reasoning', () => { + const { timing, recorded } = createTiming(); + const unobserved = timing.completeMessage('unobserved', 'Thinking', undefined); + timing.start('turn', 'sdk', 'part', undefined); + timing.append('Thinking', undefined); + const zero = timing.completeMessage('zero', 'Thinking', undefined); + timing.start('turn', 'sdk-next', 'next', undefined); + timing.append('Observed prefix', undefined); + const mismatched = timing.completeMessage('mismatch', 'Different full response', undefined); + timing.start('turn', 'sdk-interrupted', 'interrupted', undefined); + timing.append('Partial', undefined); + timing.clear(undefined); + const interrupted = timing.completeMessage('interrupted', 'Partial', undefined); + + assert.deepStrictEqual({ unobserved, zero, mismatched, interrupted, recorded }, { + unobserved: false, zero: true, mismatched: false, interrupted: false, + recorded: [{ turnId: 'turn', responseId: 'zero', timing: { startedAt: '1970-01-01T00:00:01.000Z', duration: 0 } }], + }); + }); + + test('restores timing after closing and reopening the database without timing identical historical text', async () => { + const directory = await fs.mkdtemp(join(tmpdir(), 'copilot-reasoning-timing-')); + const path = join(directory, 'session.db'); + const database = store.add(await SessionDatabase.open(path)); + let restored: SessionDatabase | undefined; + try { + const writes: Promise[] = []; + const timing = store.add(new CopilotReasoningTiming( + () => { }, + (turnId, responseId, value) => writes.push(database.setReasoningTiming(turnId, responseId, value)), + )); + timing.start('host-turn', 'sdk-reasoning', 'live-part', undefined); + timing.append('Thinking', undefined); + elapsed = 45_000; + timing.completeMessage('assistant-timed', 'Thinking', undefined); + await Promise.all(writes); + await database.close(); + restored = store.add(await SessionDatabase.open(path)); + const session = URI.parse('ahp-session:/opaque-session'); + const result = await mapSessionEvents(session, restored, toSessionEvents([ + { type: 'user.message', id: 'user-timed', data: { content: 'First request' } }, + { type: 'assistant.message', id: 'assistant-timed', data: { content: 'Done', reasoningText: 'Thinking' } }, + { type: 'user.message', id: 'user-older', data: { content: 'Older request' } }, + { type: 'assistant.message', id: 'assistant-older', data: { content: 'Done', reasoningText: 'Thinking' } }, + ]), URI.parse('ahp-chat:/opaque-chat'), session); + + assert.deepStrictEqual(result.turns.flatMap(turn => turn.responseParts.flatMap(part => part.kind === ResponsePartKind.Reasoning + ? [{ content: part.content, startedAt: part.startedAt, duration: part.duration }] : [])), [ + { content: 'Thinking', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, + { content: 'Thinking', startedAt: undefined, duration: undefined }, + ]); + } finally { + await restored?.close(); + await database.close(); + await fs.rm(directory, { recursive: true, force: true }); + } + }); +}); diff --git a/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts b/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts index 9c9106f6d6451..a3906b409c7c4 100644 --- a/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts +++ b/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts @@ -1018,7 +1018,7 @@ suite('SessionDatabase', () => { tables: await db.getAllTables(), records: await db.getPersistedTurns(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], records: [{ kind: 'local', turnId: 'local-1', chatUri: 'chat', anchorTurnId: undefined, seq: 1, payload: '{"id":"local-1"}' }], }); }); @@ -1122,6 +1122,42 @@ suite('SessionDatabase', () => { }); }); + suite('reasoning timing', () => { + test('reads submitted writes and preserves a recorded zero', async () => { + db = disposables.add(await SessionDatabase.open(':memory:')); + const startedAt = '1970-01-01T00:00:01.000Z'; + const write = db.setReasoningTiming('turn-1', 'response-1', { startedAt, duration: 45_000 }); + const first = [...await db.getReasoningTimings()]; + await write; + await db.setReasoningTiming('turn-1', 'response-1', { startedAt, duration: 0 }); + + assert.deepStrictEqual({ first, updated: [...await db.getReasoningTimings()] }, { + first: [['response-1', { startedAt, duration: 45_000 }]], + updated: [['response-1', { startedAt, duration: 0 }]], + }); + }); + + test('fork remapping preserves timing and pruning removes it', async () => { + db = disposables.add(await SessionDatabase.open(':memory:')); + const timing = { startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }; + await db.setReasoningTiming('old-1', 'response-1', timing); + await db.setReasoningTiming('old-2', 'response-2', timing); + await db.remapTurnIds(new Map([['old-1', 'new-1']])); + const forked = [...await db.getReasoningTimings()]; + await db.deleteTurn('new-1'); + + assert.deepStrictEqual({ forked, pruned: [...await db.getReasoningTimings()] }, { + forked: [['response-1', timing]], pruned: [], + }); + }); + + test('rejects invalid reasoning timing', async () => { + db = disposables.add(await SessionDatabase.open(':memory:')); + await assert.rejects(db.setReasoningTiming('turn', 'response', { startedAt: 'invalid', duration: 1 }), /Invalid reasoning timing/); + await assert.rejects(db.setReasoningTiming('turn', 'response', { startedAt: '1970-01-01T00:00:01.000Z', duration: -1 }), /Invalid reasoning timing/); + }); + }); + // ---- Turn usage ------------------------------------------------------ suite('turn usage', () => { @@ -1997,7 +2033,7 @@ suite('SessionDatabase', () => { title: await db.getMetadata('customTitle'), snapshot: await db.getCatalogSyncSnapshot(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], title: 'After upgrade', snapshot: snapshot(1), }); @@ -2024,7 +2060,7 @@ suite('SessionDatabase', () => { tables: await upgraded.getAllTables(), snapshot: await upgraded.getCatalogSyncSnapshot(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], snapshot: snapshot(1), }); }); diff --git a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/agentHostSessionHandler.ts b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/agentHostSessionHandler.ts index 69c560b84cad8..9b4ee3ef04478 100644 --- a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/agentHostSessionHandler.ts +++ b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/agentHostSessionHandler.ts @@ -164,7 +164,7 @@ import { ICopilotHomeService } from '../../../../../services/environment/common/ import { toolDataToDefinition } from './agentHostToolUtils.js'; import { IAgentHostUntitledProvisionalSessionService } from './agentHostUntitledProvisionalSessionService.js'; import { IAgentHostImportConversation, IAgentHostImportConversationStore } from './agentHostImportConversationStore.js'; -import { activeTurnToProgress, appendToolOutput, BOOLEAN_TRUE_OPTION_ID, canOwnSubagentChat, chatUsageToSessionCost, completedToolCallToEditParts, completedToolCallToSerialized, containsAutomaticReplyAnswer, convertProtocolAnswers, createInputRequestCarousel, createInputRequestPlanReview, finalizeToolInvocation, formatTurnResponseDetails, getAgentHostActivityProgressId, getTerminalContent, getUrlInputRequestPresentation, isSubagentTool, makeAhpTerminalToolSessionId, messageAttachmentsToVariableData, messageToRequestOrigin, messageToRequestSource, messageToVariableData, parseAhpTerminalToolSessionId, rewriteAgentHostLinkTarget, shouldObserveSubagentChat, stringOrMarkdownToString, systemNotificationToChatPart, toolCallAuthenticationServer, toolCallStateToInvocation, toolCallStateToPreparedInvocation, toolCallStateToStreamingInvocation, turnsToHistory, turnToResponseDetails, turnToResultMetadata, updateRunningToolSpecificData, updateStreamingToolInvocation, usageInfoToAutoModeResolution, usageInfoToChatUsage, usageInfoToQuotas, type IAgentHostToolInvocationOptions, type ITurnModelInfo, type TurnModelLookup } from './stateToProgressAdapter.js'; +import { activeTurnToProgress, appendToolOutput, BOOLEAN_TRUE_OPTION_ID, canOwnSubagentChat, chatUsageToSessionCost, completedToolCallToEditParts, completedToolCallToSerialized, containsAutomaticReplyAnswer, convertProtocolAnswers, createInputRequestCarousel, createInputRequestPlanReview, finalizeToolInvocation, formatTurnResponseDetails, getAgentHostActivityProgressId, getTerminalContent, getUrlInputRequestPresentation, isSubagentTool, makeAhpTerminalToolSessionId, messageAttachmentsToVariableData, messageToRequestOrigin, messageToRequestSource, messageToVariableData, parseAhpTerminalToolSessionId, reasoningPartToThinking, rewriteAgentHostLinkTarget, shouldObserveSubagentChat, stringOrMarkdownToString, systemNotificationToChatPart, toolCallAuthenticationServer, toolCallStateToInvocation, toolCallStateToPreparedInvocation, toolCallStateToStreamingInvocation, turnsToHistory, turnToResponseDetails, turnToResultMetadata, updateRunningToolSpecificData, updateStreamingToolInvocation, usageInfoToAutoModeResolution, usageInfoToChatUsage, usageInfoToQuotas, type IAgentHostToolInvocationOptions, type ITurnModelInfo, type TurnModelLookup } from './stateToProgressAdapter.js'; import { COPILOT_HYDRA_FUSION_MODEL_NAMES, isCopilotHydraFusionModelId } from '../../../../../../platform/agentHost/common/copilotCliConfig.js'; import { getFusionTierLabel } from '../../widget/input/modelPicker/modelPickerPresentation.js'; import { autoAuthenticateMcpServer, agentHostMcpServerId, modelRequiresAgentAuthentication } from './agentHostAuth.js'; @@ -4663,14 +4663,20 @@ export class AgentHostSessionHandler extends Disposable implements IChatSessionC ): void { const partId = part$.get().id; let lastEmitted = opts.seedEmittedLengths?.get(partId) ?? 0; + const initial = lastEmitted > 0 ? reasoningPartToThinking(part$.get()) : undefined; + let lastStartedAt = initial?.reasoningStartedAt; + let lastDuration = initial?.reasoningDurationMs; store.add(autorun(reader => { - const content = part$.read(reader).content; - if (content.length <= lastEmitted) { + const part = part$.read(reader); + const progress = reasoningPartToThinking(part, part.content.substring(lastEmitted)); + if (!part.content || (part.content.length <= lastEmitted + && progress.reasoningStartedAt === lastStartedAt && progress.reasoningDurationMs === lastDuration)) { return; } - const delta = content.substring(lastEmitted); - lastEmitted = content.length; - opts.sink([{ kind: 'thinking', value: delta, id: partId }]); + lastEmitted = part.content.length; + lastStartedAt = progress.reasoningStartedAt; + lastDuration = progress.reasoningDurationMs; + opts.sink([progress]); })); } diff --git a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/importLocalConversationToAgentSession.ts b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/importLocalConversationToAgentSession.ts index 976f5a50016cb..ac109ff764067 100644 --- a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/importLocalConversationToAgentSession.ts +++ b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/importLocalConversationToAgentSession.ts @@ -179,7 +179,14 @@ function responsePartsFromRequest(request: IChatRequestModel): ResponsePart[] { } else if (part.kind === 'thinking') { const content = Array.isArray(part.value) ? part.value.join('') : (part.value ?? ''); if (content) { - responseParts.push({ kind: ResponsePartKind.Reasoning, id: generateUuid(), content }); + const startedAt = part.reasoningStartedAt === undefined ? undefined : new Date(part.reasoningStartedAt); + responseParts.push({ + kind: ResponsePartKind.Reasoning, + id: generateUuid(), + content, + ...(startedAt && Number.isFinite(startedAt.getTime()) ? { startedAt: startedAt.toISOString() } : {}), + ...(part.reasoningDurationMs !== undefined && Number.isFinite(part.reasoningDurationMs) && part.reasoningDurationMs >= 0 ? { duration: part.reasoningDurationMs } : {}), + }); } } else if (part.kind === 'inlineReference') { // A file/symbol chip interleaved with the response text; render it diff --git a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts index 4609ad7572acd..f477e7dc8ad1e 100644 --- a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts +++ b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts @@ -43,12 +43,12 @@ import { AGENT_HOST_SESSION_LINK_SCHEME, buildOpenSessionLinkUri, isCreateChatTo import { getAgentHostChatId } from '../../../../../../platform/agentHost/common/agentHostChatIdentity.js'; import { parsePartialToolInputForDisplay } from '../../../../../../platform/agentHost/common/partialToolInput.js'; import { AuthenticateTargetKind } from '../../../../../../platform/agentHost/common/state/sessionProtocol.js'; -import { MessageAttachmentKind, type FileEdit, type MessageAttachment, type ResponsePart, type StringOrMarkdown, type TextRange } from '../../../../../../platform/agentHost/common/state/protocol/state.js'; +import { MessageAttachmentKind, type FileEdit, type MessageAttachment, type ReasoningResponsePart, type ResponsePart, type StringOrMarkdown, type TextRange } from '../../../../../../platform/agentHost/common/state/protocol/state.js'; import { normalizeFileEdit } from '../../../../../../platform/agentHost/common/fileEditDiff.js'; import { AgentSession } from '../../../../../../platform/agentHost/common/agentService.js'; import product from '../../../../../../platform/product/common/product.js'; import { ConfigureAutomationToolReferenceName } from '../../../common/automations/automationService.js'; -import { formatCopilotCreditsLabel, getSubagentIsActive, ElicitationState, type ChatExternalEditKind, type ChatMcpAppData, type IChatAgentFeedbackReviewConfirmationData, type IChatAutomationConfiguredData, type IChatAutoModeResolutionPart, type IChatExternalEdit, type IChatGeneratedImageData, type IChatMcpAuthenticationRequiredServer, type IChatModifiedFilesConfirmationData, type IChatProgress, type IChatQuestion, type IChatQuestionAnswerValue, type IChatQuestionAnswers, type IChatResponseErrorDetails, type IChatSearchToolInvocationData, type IChatSessionTargetData, type IChatSubagentToolInvocationData, type IChatTerminalToolInvocationData, type IChatToolInputInvocationData, type IChatToolInvocationSerialized, type IChatUsage, type IChatUsagePromptTokenDetail, ToolConfirmKind, AgentFeedbackReviewCommandId } from '../../../common/chatService/chatService.js'; +import { formatCopilotCreditsLabel, getSubagentIsActive, ElicitationState, type ChatExternalEditKind, type ChatMcpAppData, type IChatAgentFeedbackReviewConfirmationData, type IChatAutomationConfiguredData, type IChatAutoModeResolutionPart, type IChatExternalEdit, type IChatGeneratedImageData, type IChatMcpAuthenticationRequiredServer, type IChatModifiedFilesConfirmationData, type IChatProgress, type IChatQuestion, type IChatQuestionAnswerValue, type IChatQuestionAnswers, type IChatResponseErrorDetails, type IChatSearchToolInvocationData, type IChatSessionTargetData, type IChatSubagentToolInvocationData, type IChatTerminalToolInvocationData, type IChatThinkingPart, type IChatToolInputInvocationData, type IChatToolInvocationSerialized, type IChatUsage, type IChatUsagePromptTokenDetail, ToolConfirmKind, AgentFeedbackReviewCommandId } from '../../../common/chatService/chatService.js'; import { isTerminalCommandPrompt, type IChatSessionHistoryItem } from '../../../common/chatSessionsService.js'; import { type IQuotaSnapshot, type IRateLimitSnapshot } from '../../../../../services/chat/common/chatEntitlementService.js'; import { ChatToolInvocation } from '../../../common/model/chatProgressTypes/chatToolInvocation.js'; @@ -1303,7 +1303,7 @@ export function turnsToHistory(backendSession: URI, turns: readonly Turn[], part } case ResponsePartKind.Reasoning: if (rp.content) { - parts.push({ kind: 'thinking', value: rp.content, id: rp.id }); + parts.push(reasoningPartToThinking(rp)); } break; case ResponsePartKind.SystemNotification: @@ -1693,6 +1693,17 @@ function textRangeToIRange(range: TextRange): IRange { }; } +export function reasoningPartToThinking(part: ReasoningResponsePart, value = part.content): IChatThinkingPart { + const startedAt = part.startedAt === undefined ? undefined : Date.parse(part.startedAt); + return { + kind: 'thinking', + id: part.id, + value, + ...(startedAt !== undefined && Number.isFinite(startedAt) ? { reasoningStartedAt: startedAt } : {}), + ...(typeof part.duration === 'number' && Number.isFinite(part.duration) && part.duration >= 0 ? { reasoningDurationMs: part.duration } : {}), + }; +} + /** * Converts an active (in-progress) turn's accumulated state into progress * items suitable for replaying into the chat UI when reconnecting to a @@ -1718,7 +1729,7 @@ export function activeTurnToProgress(sessionResource: URI, activeTurn: ActiveTur break; case ResponsePartKind.Reasoning: if (rp.content) { - parts.push({ kind: 'thinking', value: rp.content, id: rp.id }); + parts.push(reasoningPartToThinking(rp)); } break; case ResponsePartKind.ToolCall: { diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts index 2f2f855e96078..5e3b93f9839ea 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts +++ b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts @@ -48,6 +48,7 @@ import { URI } from '../../../../../../base/common/uri.js'; import { IUriIdentityService } from '../../../../../../platform/uriIdentity/common/uriIdentity.js'; import { getToolGroupSummary } from './chatToolGroupSummary.js'; import { ChatActivityLabelTransition } from './chatActivityLabelTransition.js'; +import { formatElapsedTime } from '../../../common/chatProgressFormatting.js'; // Context key id mirrored from `vs/sessions/common/contextkeys` (`IsPhoneLayoutContext`). @@ -357,8 +358,22 @@ export function buildPhrasePool(defaults: string[], configurationService: IConfi return [...defaults]; } -function getFinishedThinkingTitle(): string { - return localize('chat.thinking.finishedThinking', "Finished thinking"); +function getFinishedThinkingTitle(parts: readonly IChatThinkingPart[]): string { + let duration = 0; + let hasTiming = false; + for (const part of parts) { + if (!extractTextFromPart(part).trim()) { + continue; + } + if (part.reasoningDurationMs === undefined || !Number.isFinite(part.reasoningDurationMs) || part.reasoningDurationMs < 0) { + return localize('chat.thinking.finishedThinking', "Finished thinking"); + } + duration += part.reasoningDurationMs; + hasTiming = true; + } + return hasTiming + ? localize('chat.thinking.thoughtFor', "Thought for {0}", formatElapsedTime(duration)) + : localize('chat.thinking.finishedThinking', "Finished thinking"); } export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implements IChatContentPart { @@ -505,7 +520,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem const extractedTitle = extractTitleFromThinkingContent(initialText) ?? localize('chat.thinking.header.initial', 'Thinking'); const initialTitle = streamingCompleted && !context.isToolChain - ? getFinishedThinkingTitle() + ? getFinishedThinkingTitle([content]) : context.suppressProgressShimmer && !context.isToolChain ? localize('chat.thinking.header.initial', 'Thinking') : extractedTitle; @@ -1646,6 +1661,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem this.thinkingHeadersByPart.delete(content); const needsInitialRender = this.textContainer ? !this.textContainer.hasChildNodes() : this.isPersistentReasoning || this.isConversation; if (next === this.currentThinkingValue && !needsInitialRender) { + this.updateDropdownClickability(); return; } const previousValue = this.currentThinkingValue; @@ -1942,7 +1958,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem private getFallbackTitle(): string { if (!this.isToolChain) { - return getFinishedThinkingTitle(); + return getFinishedThinkingTitle([...new Set(this.allThinkingParts.map(part => this.thinkingPartSources?.get(part) ?? part))]); } const visibleItemCount = this.appendedItemCount - this.hiddenToolCallIds.size; diff --git a/src/vs/workbench/contrib/chat/common/model/chatModel.ts b/src/vs/workbench/contrib/chat/common/model/chatModel.ts index 3380133c81900..8d534d7e9206d 100644 --- a/src/vs/workbench/contrib/chat/common/model/chatModel.ts +++ b/src/vs/workbench/contrib/chat/common/model/chatModel.ts @@ -1056,6 +1056,23 @@ export class Response extends AbstractResponse implements IDisposable { } this._contentChanged(quiet); } else if (progress.kind === 'thinking') { + const hasTiming = progress.reasoningStartedAt !== undefined || progress.reasoningDurationMs !== undefined; + const timing = { + ...(progress.reasoningStartedAt !== undefined ? { reasoningStartedAt: progress.reasoningStartedAt } : {}), + ...(progress.reasoningDurationMs !== undefined ? { reasoningDurationMs: progress.reasoningDurationMs } : {}), + }; + if (hasTiming && this._activeReasoning?.part.id === progress.id) { + this._activeReasoning = undefined; + } + if (hasTiming && progress.id !== undefined && !progress.value?.length) { + const index = this._responseParts.findIndex(part => part.kind === 'thinking' && part.id === progress.id); + const part = this._responseParts[index]; + if (part?.kind === 'thinking') { + Object.assign(part, timing); + this._contentChanged(quiet); + return; + } + } // tries to split thinking chunks if it is an array. only while certain models give us array chunks. // Nested subagent parts render inside their parent card and must not split parent reasoning. @@ -1067,10 +1084,14 @@ export class Response extends AbstractResponse implements IDisposable { ? (Array.isArray(lastResponsePart.value) ? lastResponsePart.value.join('') : (lastResponsePart.value || '')) : ''; const currText = Array.isArray(progress.value) ? progress.value.join('') : (progress.value || ''); + const differentId = lastResponsePart?.kind === 'thinking' && progress.id !== undefined && lastResponsePart.id !== undefined && progress.id !== lastResponsePart.id; + if (differentId) { + this.finalizeReasoningDuration(); + } const isEmpty = (s: string) => s.length === 0; if (isEmpty(currText)) { this.finalizeReasoningDuration(); - } else if (!this._activeReasoning && !restored) { + } else if (!this._activeReasoning && !restored && !hasTiming) { // Replayed history keeps its recorded timing; this clock only measures live reasoning. this._activeReasoning = { part: progress, startedAt: Date.now() }; } @@ -1080,16 +1101,18 @@ export class Response extends AbstractResponse implements IDisposable { || lastResponsePart.kind !== 'thinking' || isEmpty(currText) || isEmpty(lastText) + || differentId || !canMergeMarkdownStrings(new MarkdownString(lastText), new MarkdownString(currText))) { this._responseParts.push(progress); } else { const idx = this._responseParts.indexOf(lastResponsePart); const mergedPart: IChatThinkingPart = { ...lastResponsePart, + ...timing, value: appendMarkdownString(new MarkdownString(lastText), new MarkdownString(currText)).value }; this._responseParts[idx] = mergedPart; - if (this._activeReasoning?.part === lastResponsePart) { + if (this._activeReasoning?.part === lastResponsePart || this._activeReasoning?.part === progress) { this._activeReasoning.part = mergedPart; } } diff --git a/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts b/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts index 8f26c266c6bc3..ae4d90eef02bd 100644 --- a/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts @@ -23,7 +23,7 @@ import { getSubagentEditorResource } from '../../../browser/widget/chatContentPa import { URI } from '../../../../../../base/common/uri.js'; import { IAgentHostConnectionsService } from '../../../../../../platform/agentHost/common/agentHostConnectionsService.js'; import { AgentHostConnectionsService } from '../../../../../../platform/agentHost/browser/agentHostConnectionsService.js'; -import { autorun, constObservable, derived, ISettableObservable, observableValue, type IObservable } from '../../../../../../base/common/observable.js'; +import { autorun, constObservable, derived, ISettableObservable, observableValue, waitForState, type IObservable } from '../../../../../../base/common/observable.js'; import { mock, upcastPartial } from '../../../../../../base/test/common/mock.js'; import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../../../base/test/common/utils.js'; import { runWithFakedTimers } from '../../../../../../base/test/common/timeTravelScheduler.js'; @@ -18444,6 +18444,43 @@ suite('AgentHostChatContribution', () => { assert.deepStrictEqual(session.progressObs?.get(), []); }); + test('receives timing-only reasoning updates after reconnect on an opaque advertised chat', async () => { + const { sessionHandler, agentHostService } = createContribution(disposables, { backendSessionScheme: 'unused-allocation-scheme' }); + const sessionUri = URI.parse('ahp-session:/opaque-reasoning-session'); + const chatUri = 'ahp-chat:/host-chosen-reasoning-chat'; + const state = makeSessionStateWithActiveTurn(sessionUri.toString()); + agentHostService.seedSessionMetadata(sessionUri, 'copilot'); + agentHostService.sessionStates.set(sessionUri.toString(), { + ...state, + defaultChat: chatUri, + chats: [{ resource: chatUri, title: state.title, status: SessionStatus.InProgress, modifiedAt: '2025-01-01T00:00:00.000Z', origin: { kind: ChatOriginKind.User } }], + activeTurn: { + ...state.activeTurn!, + responseParts: [{ kind: ResponsePartKind.Reasoning, id: 'reasoning', content: 'Already received', startedAt: '1970-01-01T00:00:01.000Z' }], + }, + }); + const session = await sessionHandler.provideChatSessionContent(URI.parse('agent-host-copilot:/opaque-reasoning-session'), CancellationToken.None); + disposables.add(toDisposable(() => session.dispose())); + assert.ok(session.isCompleteObs); + const completed = waitForState(session.isCompleteObs, complete => complete); + const action = { type: ActionType.ChatReasoning as const, turnId: 'turn-active', partId: 'reasoning', content: '', duration: 45_000 }; + agentHostService.fireAction({ channel: chatUri, action, serverSeq: 100, origin: undefined }); + agentHostService.fireAction({ channel: chatUri, action, serverSeq: 101, origin: undefined }); + agentHostService.fireAction({ channel: chatUri, action: { type: ActionType.ChatTurnComplete, turnId: 'turn-active', duration: 50_000 }, serverSeq: 102, origin: undefined }); + await completed; + + assert.deepStrictEqual({ + parts: session.progressObs?.get().filter(part => part.kind === 'thinking'), + complete: session.isCompleteObs?.get(), + }, { + parts: [ + { kind: 'thinking', id: 'reasoning', value: 'Already received', reasoningStartedAt: 1000 }, + { kind: 'thinking', id: 'reasoning', value: '', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + ], + complete: true, + }); + }); + test('includes reasoning in initial progress', async () => { const { sessionHandler, agentHostService } = createContribution(disposables); diff --git a/src/vs/workbench/contrib/chat/test/browser/agentSessions/importLocalConversationToAgentSession.test.ts b/src/vs/workbench/contrib/chat/test/browser/agentSessions/importLocalConversationToAgentSession.test.ts index 6d1b4dbd60d55..5ba327a2aecbf 100644 --- a/src/vs/workbench/contrib/chat/test/browser/agentSessions/importLocalConversationToAgentSession.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/agentSessions/importLocalConversationToAgentSession.test.ts @@ -86,6 +86,21 @@ suite('importedTurnsFromChatModel', () => { })); } + test('preserves local reasoning timing when importing into an agent session', () => { + const turns = importedTurnsFromChatModel(model([request('q', response([ + { kind: 'thinking', value: 'Measured', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', value: 'Immediate', reasoningDurationMs: 0 }, + { kind: 'thinking', value: 'Older history' }, + ]))])); + + assert.deepStrictEqual(turns[0].responseParts.flatMap(part => part.kind === ResponsePartKind.Reasoning + ? [{ content: part.content, startedAt: part.startedAt, duration: part.duration }] : []), [ + { content: 'Measured', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, + { content: 'Immediate', startedAt: undefined, duration: 0 }, + { content: 'Older history', startedAt: undefined, duration: undefined }, + ]); + }); + test('maps markdown, reasoning and inline references in stream order', () => { const result = project(model([request('q', response([ markdown('Found in '), diff --git a/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts b/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts index 59506e35128d9..3a5d02824bf15 100644 --- a/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts @@ -1063,6 +1063,24 @@ suite('stateToProgressAdapter', () => { assert.strictEqual(thinking.id, 'r-1'); }); + test('restores producer reasoning timing without inventing timing for older hosts', () => { + const history = turnsToHistory(URI.parse('external:/opaque/session'), [createTurn({ + responseParts: [ + { kind: ResponsePartKind.Reasoning, id: 'timed', content: 'Measured', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, + { kind: ResponsePartKind.Reasoning, id: 'zero', content: 'Immediate', duration: 0 }, + { kind: ResponsePartKind.Reasoning, id: 'unknown', content: 'Older host' }, + { kind: ResponsePartKind.Reasoning, id: 'invalid', content: 'Invalid metadata', startedAt: 'invalid', duration: -1 }, + ], + })], 'participant'); + + assert.deepStrictEqual(history[1].type === 'response' ? history[1].parts : undefined, [ + { kind: 'thinking', id: 'timed', value: 'Measured', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'zero', value: 'Immediate', reasoningDurationMs: 0 }, + { kind: 'thinking', id: 'unknown', value: 'Older host' }, + { kind: 'thinking', id: 'invalid', value: 'Invalid metadata' }, + ]); + }); + test('generic completed tool call in history includes input/output details', () => { const turn = createTurn({ responseParts: [{ @@ -4545,6 +4563,18 @@ suite('stateToProgressAdapter', () => { assert.strictEqual((result[0] as IChatThinkingPart).id, 'r-1'); }); + test('preserves completed and unfinished reasoning timing on reconnect', () => { + const result = activeTurnToProgress(URI.parse('external:/opaque/session'), createActiveTurnState([ + { kind: ResponsePartKind.Reasoning, id: 'completed', content: 'Already thought', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, + { kind: ResponsePartKind.Reasoning, id: 'active', content: 'Still thinking', startedAt: '1970-01-01T00:01:00.000Z' }, + ]), 'remote-host'); + + assert.deepStrictEqual(result, [ + { kind: 'thinking', id: 'completed', value: 'Already thought', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'active', value: 'Still thinking', reasoningStartedAt: 60_000 }, + ]); + }); + test('reasoning comes before streamed text when ordered that way', () => { const result = activeTurnToProgress(URI.file('/'), createActiveTurnState([ { kind: ResponsePartKind.Reasoning, id: 'r-1', content: 'Hmm...' }, diff --git a/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts b/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts index 95e24b5fd54a8..56382901237dd 100644 --- a/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts @@ -2086,7 +2086,7 @@ suite('ChatThinkingContentPart', () => { }); }); - test('does not use reasoning duration in the generic title', async () => { + test('uses recorded reasoning duration in the generic title', async () => { const first = createThinkingPart('Consider how to update the progress renderer.', 'first'); first.reasoningStartedAt = 1000; first.reasoningDurationMs = 1200; @@ -2100,8 +2100,8 @@ suite('ChatThinkingContentPart', () => { await timeout(0); assert.deepStrictEqual({ title: snapshot(part).title, ariaLabel: snapshot(part).ariaLabel }, { - title: 'Finished thinking', - ariaLabel: 'Finished thinking', + title: 'Thought for 3s', + ariaLabel: 'Thought for 3s', }); }); }); @@ -2374,7 +2374,7 @@ suite('ChatThinkingContentPart', () => { }); }); - test('finished sections use the same fallback with or without recorded timing', () => { + test('finished sections report only recorded reasoning time and not tool time', () => { type Case = { readonly reasoning: readonly { readonly startedAt?: number; readonly durationMs?: number; readonly text?: string }[]; readonly tools: readonly (readonly [startedAt?: number, completedAt?: number])[] }; const cases: Record = { shortReasoning: { reasoning: [{ startedAt: 1000, durationMs: 400 }], tools: [] }, @@ -2404,36 +2404,36 @@ suite('ChatThinkingContentPart', () => { })); assert.deepStrictEqual(titles, { - shortReasoning: 'Finished thinking', - reasoningWithoutStart: 'Finished thinking', + shortReasoning: 'Thought for 0s', + reasoningWithoutStart: 'Thought for 2s', textlessReasoning: 'Finished thinking', textlessReasoningAndTools: 'Finished thinking', toolsOnly: 'Finished thinking', - reasoningAndTools: 'Finished thinking', - reasoningWithoutStartAndTools: 'Finished thinking', - unfinishedTool: 'Finished thinking', + reasoningAndTools: 'Thought for 1s', + reasoningWithoutStartAndTools: 'Thought for 2s', + unfinishedTool: 'Thought for 0s', restoredReasoning: 'Finished thinking', restoredTools: 'Finished thinking', restoredReasoningThenLiveTool: 'Finished thinking', - liveReasoningThenRestoredTool: 'Finished thinking', + liveReasoningThenRestoredTool: 'Thought for 1s', }); }); - test('split array reasoning uses the same fallback regardless of timing', () => { + test('split array reasoning counts each source duration once', () => { const cases: Record = { equalDurations: { parts: [ { kind: 'thinking', value: ['First', 'Second'], reasoningDurationMs: 1200 }, { kind: 'thinking', value: ['Third', 'Fourth'], reasoningDurationMs: 1200 }, ], - title: 'Finished thinking', + title: 'Thought for 2s', }, knownSpan: { parts: [ { kind: 'thinking', value: ['First', 'Second'], reasoningStartedAt: 1000, reasoningDurationMs: 1200 }, { kind: 'thinking', value: ['Third', 'Fourth'], reasoningStartedAt: 5000, reasoningDurationMs: 1200 }, ], - title: 'Finished thinking', + title: 'Thought for 2s', }, unknownTiming: { parts: [ @@ -2458,7 +2458,7 @@ suite('ChatThinkingContentPart', () => { assert.deepStrictEqual(titles, Object.fromEntries(Object.entries(cases).map(([name, { title }]) => [name, title]))); }); - test('replacing a split reasoning fragment preserves the finished fallback', () => { + test('replacing a split reasoning fragment updates the recorded duration', () => { const source = { ...createThinkingPart(undefined, 'shared'), value: ['First', 'Second'], reasoningDurationMs: 1200 }; const first = { ...source, value: 'First' }; const part = createConversationSection(first); @@ -2468,8 +2468,8 @@ suite('ChatThinkingContentPart', () => { part.finalizeTitleIfDefault(); assert.deepStrictEqual({ title: snapshot(part).title, ariaLabel: snapshot(part).ariaLabel }, { - title: 'Finished thinking', - ariaLabel: 'Finished thinking', + title: 'Thought for 2s', + ariaLabel: 'Thought for 2s', }); }); @@ -2681,7 +2681,7 @@ suite('ChatThinkingContentPart', () => { assert.strictEqual(part.hasGroupedItems(), true); }); - test('shows Finished thinking in untitled finalized headers and accessible labels', () => { + test('shows recorded reasoning duration in finalized headers and accessible labels', () => { const content = createThinkingPart('Reviewed the implementation'); content.reasoningDurationMs = 1200; const part = store.add(instantiationService.createInstance( @@ -2705,14 +2705,14 @@ suite('ChatThinkingContentPart', () => { ariaLabel: button?.ariaLabel, }, { generatedTitle: undefined, - label: 'Finished thinking', - ariaLabel: 'Finished thinking', + label: 'Thought for 1s', + ariaLabel: 'Thought for 1s', }); }); - test('does not display persisted duration when reasoning content is rehydrated', () => { + test('displays Thought for 45s when reasoning content is rehydrated', () => { const content = createThinkingPart('Reviewed the implementation'); - content.reasoningDurationMs = 2300; + content.reasoningDurationMs = 45_000; const part = store.add(instantiationService.createInstance( ChatThinkingContentPart, content, @@ -2725,11 +2725,11 @@ suite('ChatThinkingContentPart', () => { disposables.add(toDisposable(() => part.domNode.remove())); part.finalizeTitleIfDefault(); - assert.strictEqual(part.domNode.querySelector('.monaco-button')?.textContent, 'Finished thinking'); + assert.strictEqual(part.domNode.querySelector('.monaco-button')?.textContent, 'Thought for 45s'); }); - test('uses Finished thinking for zero or unavailable reasoning duration', () => { - const titles = [undefined, 0].map(reasoningDurationMs => { + test('distinguishes zero reasoning duration from unavailable or invalid timing', () => { + const titles = [undefined, 0, 999, 1000, 83_000, -1, NaN, Infinity].map(reasoningDurationMs => { const content = createThinkingPart('Reviewed the implementation'); content.reasoningDurationMs = reasoningDurationMs; const part = store.add(instantiationService.createInstance( @@ -2743,7 +2743,7 @@ suite('ChatThinkingContentPart', () => { return part.domNode.querySelector('.monaco-button')?.textContent; }); - assert.deepStrictEqual(titles, ['Finished thinking', 'Finished thinking']); + assert.deepStrictEqual(titles, ['Finished thinking', 'Thought for 0s', 'Thought for 0s', 'Thought for 1s', 'Thought for 1m 23s', 'Finished thinking', 'Finished thinking', 'Finished thinking']); }); }); diff --git a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts index bc0296e35b2ca..9f5b6c341ca6f 100644 --- a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts +++ b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts @@ -995,6 +995,54 @@ suite('ChatModel', () => { } }); + test('applies timing-only reasoning updates without replaying text or measuring a remote clock', () => { + const clock = sinon.useFakeTimers({ now: 900_000 }); + try { + const response = testDisposables.add(new Response([])); + response.updateContent({ kind: 'thinking', id: 'reasoning', value: 'First', reasoningStartedAt: 1000 }); + response.updateContent({ kind: 'thinking', id: 'reasoning', value: ' thought', reasoningStartedAt: 1000 }); + const renderedPart = response.value[0]; + clock.tick(5000); + response.updateContent({ kind: 'markdownContent', content: new MarkdownString('Done') }); + response.updateContent({ kind: 'thinking', id: 'reasoning', value: '', reasoningDurationMs: 45_000 }); + response.finalizeReasoningDuration(); + + assert.deepStrictEqual({ parts: response.value, keepsRenderedPart: response.value[0] === renderedPart }, { + parts: [ + { kind: 'thinking', id: 'reasoning', value: 'First thought', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'markdownContent', content: new MarkdownString('Done') }, + ], + keepsRenderedPart: true, + }); + } finally { + clock.restore(); + } + }); + + test('keeps consecutive reasoning ids and zero durations distinct', () => { + const response = testDisposables.add(new Response([])); + response.updateContent({ kind: 'thinking', id: 'first', value: 'First', reasoningDurationMs: 45_000 }); + response.updateContent({ kind: 'thinking', id: 'second', value: 'Second', reasoningDurationMs: 0 }); + response.finalizeReasoningDuration(); + + assert.deepStrictEqual(response.value, [ + { kind: 'thinking', id: 'first', value: 'First', reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'second', value: 'Second', reasoningDurationMs: 0 }, + ]); + }); + + test('recorded reasoning timing survives chat model serialization and restoration', () => { + const model = testDisposables.add(instantiationService.createInstance(ChatModel, undefined, { initialLocation: ChatAgentLocation.Chat, canUseTools: true })); + const request = model.addRequest({ text: 'hello', parts: [] }, { variables: [] }, 0); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'reasoning', value: 'Working through it', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }); + request.response?.complete(); + const restored = testDisposables.add(instantiationService.createInstance(ChatModel, { value: model.toJSON(), serializer: undefined! }, { initialLocation: ChatAgentLocation.Chat, canUseTools: true })); + + assert.deepStrictEqual(restored.getRequests()[0].response?.entireResponse.value, [ + { kind: 'thinking', id: 'reasoning', value: 'Working through it', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + ]); + }); + test('leaves tool calls replayed from history untimed', async () => { const clock = sinon.useFakeTimers({ now: 9000 }); try { From 74a36bfc757ad0ad2437919961afebb975c0fc3d Mon Sep 17 00:00:00 2001 From: Justin Chen Date: Thu, 29 Oct 2026 22:11:11 -0700 Subject: [PATCH 2/4] chat: preserve timing for each contiguous thinking run Keep one reasoning identity and clock until markdown, a new tool call, or turn termination. Persist the observed response-part ordering and update runs that span SDK messages, rather than storing message-level totals. Restore separate run durations and canonical tool positions, retain conversation grouping with per-run labels, and cover 5s/12s boundaries across database restart and UI reload. Pin the clarified contract from microsoft/agent-host-protocol#552. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../agentHost/common/sessionDataService.ts | 17 +- .../common/state/protocol/.ahp-version | 2 +- .../node/compatibleSessionDatabase.ts | 8 +- .../agentHost/node/copilot/copilotAgent.ts | 1 + .../node/copilot/copilotAgentSession.ts | 65 ++--- .../node/copilot/copilotReasoningTiming.ts | 231 +++++++++++++--- .../node/copilot/mapSessionEvents.ts | 34 ++- .../agentHost/node/sessionDatabase.ts | 58 +++- .../test/common/sessionTestHelpers.ts | 35 ++- src/vs/platform/agentHost/test/node/README.md | 8 +- .../test/node/copilotAgentSession.test.ts | 60 +++- .../test/node/copilotReasoningTiming.test.ts | 256 ++++++++++++------ .../test/node/sessionDatabase.test.ts | 52 ++-- .../chatThinkingContentPart.ts | 84 +++++- .../media/chatThinkingContent.css | 5 + .../chat/browser/widget/chatListRenderer.ts | 20 ++ .../contrib/chat/common/model/chatModel.ts | 24 +- .../chatThinkingContentPart.test.ts | 20 +- .../browser/widget/chatListRenderer.test.ts | 71 ++++- .../chat/test/common/model/chatModel.test.ts | 18 ++ 20 files changed, 807 insertions(+), 262 deletions(-) diff --git a/src/vs/platform/agentHost/common/sessionDataService.ts b/src/vs/platform/agentHost/common/sessionDataService.ts index 9467867a21bcb..1aab8000a050e 100644 --- a/src/vs/platform/agentHost/common/sessionDataService.ts +++ b/src/vs/platform/agentHost/common/sessionDataService.ts @@ -9,7 +9,7 @@ import { URI } from '../../../base/common/uri.js'; import { createDecorator } from '../../instantiation/common/instantiation.js'; import { Event } from '../../../base/common/event.js'; import { getLargeFileConfirmationLimit } from '../../files/common/files.js'; -import type { FileEditKind, Message } from './state/sessionState.js'; +import type { FileEditKind, MarkdownResponsePart, Message, ReasoningResponsePart, ResponsePartKind } from './state/sessionState.js'; export const ISessionDataService = createDecorator('sessionDataService'); @@ -98,11 +98,8 @@ export interface IReviewedFileRecord { // ---- Session database --------------------------------------------------- -/** A producer-measured reasoning interval, keyed by its durable provider response id. */ -export interface IReasoningTiming { - readonly startedAt: string; - readonly duration: number; -} +/** Ordered response text with stable reasoning-run identities and references to provider-owned tool results. */ +export type StoredAssistantResponsePart = MarkdownResponsePart | ReasoningResponsePart | { readonly kind: ResponsePartKind.ToolCall; readonly toolCallId: string }; /** A host-persisted turn that is absent from the provider transcript. */ export interface IPersistedTurnRecord { @@ -272,11 +269,11 @@ export interface ISessionDatabase extends IDisposable { */ getTurnUsages(): Promise>; - /** Records completed reasoning timing with the owning turn's pruning lifecycle. */ - setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise; + /** Records a response's observed part ordering and reasoning timings with the owning turn's pruning lifecycle. */ + setAssistantResponseParts(turnId: string, responseId: string, parts: readonly StoredAssistantResponsePart[]): Promise; - /** Reads recorded reasoning timings after all previously submitted writes. */ - getReasoningTimings(): Promise>; + /** Reads recorded parts keyed by durable provider response id, after all previously submitted writes. */ + getAssistantResponseParts(): Promise>; /** * Persists the JSON-serialized delegation metadata for an agent-authored turn. diff --git a/src/vs/platform/agentHost/common/state/protocol/.ahp-version b/src/vs/platform/agentHost/common/state/protocol/.ahp-version index a9fb20f1335e9..e081b9c944eb9 100644 --- a/src/vs/platform/agentHost/common/state/protocol/.ahp-version +++ b/src/vs/platform/agentHost/common/state/protocol/.ahp-version @@ -1 +1 @@ -f9d401d7 +f0cf2adc diff --git a/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts b/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts index 39333d9edcb26..2356dd43df44a 100644 --- a/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts +++ b/src/vs/platform/agentHost/node/compatibleSessionDatabase.ts @@ -72,12 +72,12 @@ export class CompatibleSessionDatabase implements ISessionDatabase { return result; } - async setReasoningTiming(...args: Parameters): ReturnType { - return this.raw.setReasoningTiming(...args); + async setAssistantResponseParts(...args: Parameters): ReturnType { + return this.raw.setAssistantResponseParts(...args); } - async getReasoningTimings(): ReturnType { - return this.raw.getReasoningTimings(); + async getAssistantResponseParts(): ReturnType { + return this.raw.getAssistantResponseParts(); } async getTurnDelegations(...[]: Parameters): ReturnType { diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgent.ts b/src/vs/platform/agentHost/node/copilot/copilotAgent.ts index 93a671d7593ca..a017891c2e085 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgent.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgent.ts @@ -7654,6 +7654,7 @@ export class CopilotAgent extends Disposable implements IAgent { try { const backing = this._chatBackings.get(context.chatKey); const result = await mapSessionEvents(context.resource, reference.object, events, context.chat, context.ownerSession, { + logService: this._logService, workingDirectory: metadata.workingDirectory, clientToolNames: new Set(this._activeClients.get(context.ownerSession)?.toolSet.merged().map(tool => tool.name) ?? []), model: backing?.model ?? metadata.model, diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts index 19f0635d83743..ab1bca7cc17e5 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgentSession.ts @@ -390,7 +390,6 @@ type IMappedSessionEvents = { turns: Turn[]; subagentTurnsByToolCallId: Readonly interface ICopilotResponsePartState { readonly markdownPartIds: Map; - readonly reasoningPartIds: Map; } function getEmptyToolResultText(binaryResults: readonly { readonly type: 'image' | 'resource' }[] | undefined): string { @@ -947,8 +946,6 @@ class CopilotTurn extends Disposable { /** Current markdown response part IDs for this root turn and its Fusion phase scopes. */ readonly markdownPartIds = new Map(); - /** Current reasoning response part IDs for this root turn and its Fusion phase scopes. */ - readonly reasoningPartIds = new Map(); readonly toolTitles = new Map(); readonly toolIntentions = new Map(); @@ -1113,13 +1110,13 @@ export class CopilotAgentSession extends Disposable { private readonly _storageUri: URI; private readonly _reasoningTiming = this._register(new CopilotReasoningTiming( (action, parentToolCallId) => this._emitProgress({ kind: 'action', resource: this._chatChannelUri, action, parentToolCallId }), - (turnId, responseId, timing) => { + (turnId, responseId, parts) => { if (!turnId) { this._logService.trace(`[Copilot:${this.sessionId}] Cannot persist reasoning timing without an owning turn`); return; } - void this._withDatabase(db => db.setReasoningTiming(turnId, responseId, timing)).catch(error => - this._logService.error(`[Copilot:${this.sessionId}] Failed to persist reasoning timing`, error)); + void this._withDatabase(db => db.setAssistantResponseParts(turnId, responseId, parts)).catch(error => + this._logService.error(`[Copilot:${this.sessionId}] Failed to persist response parts`, error)); }, )); @@ -1249,7 +1246,6 @@ export class CopilotAgentSession extends Disposable { private readonly _pendingSubagentToolCompletions = new Map>(); private readonly _subagentResponsePartState: ICopilotResponsePartState = { markdownPartIds: new Map(), - reasoningPartIds: new Map(), }; private readonly _resolveAgentName = (agentId: string) => this._subagents.getDisplayName(agentId); readonly modelCallTurnCorrelation = new ModelCallTurnCorrelation(); @@ -2387,10 +2383,18 @@ export class CopilotAgentSession extends Disposable { if (action.type === ActionType.ChatUsage && !parentToolCallId && this._launchPlan.localModelProvider) { this._lastRootUsage = { turnId: action.turnId, usage: action.usage }; } - if (action.type === ActionType.ChatDelta || action.type === ActionType.ChatToolCallStart || action.type === ActionType.ChatInputRequested - || (action.type === ActionType.ChatResponsePart && action.part.kind !== ResponsePartKind.Reasoning) - || action.type === ActionType.ChatTurnComplete || action.type === ActionType.ChatTurnCancelled || action.type === ActionType.ChatError) { + if (action.type === ActionType.ChatDelta) { + const timingTurnId = parentToolCallId ? this._subagents.getRootTurnId(parentToolCallId) ?? action.turnId : action.turnId; + this._reasoningTiming.markdown(timingTurnId, action.partId, action.content, parentToolCallId); + } else if (action.type === ActionType.ChatResponsePart && action.part.kind === ResponsePartKind.Markdown) { + const timingTurnId = parentToolCallId ? this._subagents.getRootTurnId(parentToolCallId) ?? action.turnId : action.turnId; + this._reasoningTiming.markdown(timingTurnId, action.part.id, action.part.content, parentToolCallId); + } else if (action.type === ActionType.ChatToolCallStart) { + const timingTurnId = parentToolCallId ? this._subagents.getRootTurnId(parentToolCallId) ?? action.turnId : action.turnId; + this._reasoningTiming.toolCall(timingTurnId, action.toolCallId, parentToolCallId); + } else if (action.type === ActionType.ChatTurnComplete || action.type === ActionType.ChatTurnCancelled || action.type === ActionType.ChatError) { this._reasoningTiming.finish(parentToolCallId); + this._reasoningTiming.clear(parentToolCallId); } this._emitProgress({ kind: 'action', @@ -3379,15 +3383,12 @@ export class CopilotAgentSession extends Disposable { this._reasoningTiming.finish(parentToolCallId); this._reasoningTiming.clear(parentToolCallId); this._subagentResponsePartState.markdownPartIds.delete(parentToolCallId); - this._subagentResponsePartState.reasoningPartIds.delete(parentToolCallId); } private _beginToolCallRound(parentToolCallId: string | undefined): void { - this._reasoningTiming.finish(parentToolCallId); const scope = parentToolCallId ?? ''; const state = this._getResponsePartState(parentToolCallId); state?.markdownPartIds.delete(scope); - state?.reasoningPartIds.delete(scope); } /** @@ -3839,10 +3840,13 @@ export class CopilotAgentSession extends Disposable { } /** Emits a reasoning delta, similar to {@link _emitMarkdownDelta} but for reasoning parts. */ - private _emitReasoningDelta(content: string, reasoningId: string, parentToolCallId?: string): void { + private _emitReasoningDelta(content: string, parentToolCallId?: string): void { if (this._shouldDropLateRootTurnEvent('assistant.reasoning_delta')) { return; } + if (!content) { + return; + } const state = this._getResponsePartState(parentToolCallId); if (!state) { this._logService.error(`[Copilot:${this.sessionId}] Reasoning delta emitted with no active turn; dropping`); @@ -3850,14 +3854,11 @@ export class CopilotAgentSession extends Disposable { } const reasoningScope = parentToolCallId ?? ''; const timingTurnId = parentToolCallId ? this._subagents.getRootTurnId(parentToolCallId) ?? this._turnId : this._turnId; - let partId = state.reasoningPartIds.get(reasoningScope); - if (partId !== this._reasoningTiming.activePartId(timingTurnId, reasoningId, parentToolCallId)) { - partId = undefined; - } + let partId = this._reasoningTiming.activePartId(timingTurnId, parentToolCallId); if (!partId) { partId = generateUuid(); - state.reasoningPartIds.set(reasoningScope, partId); - const startedAt = this._reasoningTiming.start(timingTurnId, reasoningId, partId, parentToolCallId); + state.markdownPartIds.delete(reasoningScope); + const startedAt = this._reasoningTiming.start(timingTurnId, partId, parentToolCallId); this._reasoningTiming.append(content, parentToolCallId); this._emitAction({ type: ActionType.ChatResponsePart, @@ -6885,6 +6886,7 @@ export class CopilotAgentSession extends Disposable { this._logService.trace(`[Copilot:${this.sessionId}] Read ${events.length} persisted event(s); reconstructing turns`); return this._withDatabase(async db => { const result = await mapSessionEvents(this._storageUri, db, events, this._chatChannelUri, this._ownerSessionUri, { + logService: this._logService, workingDirectory: this._workingDirectory, clientToolNames: this._clientToolNames, model: this._launchPlan.kind === 'create' @@ -9175,8 +9177,6 @@ export class CopilotAgentSession extends Disposable { this._logService.info(`[Copilot:${sessionId}] System notification received: kind=${e.data.kind.type}`); if (this._turnId) { - // Later parent reasoning belongs after this notice; child reasoning keeps its own stream. - this._currentTurn.value?.reasoningPartIds.delete(''); this._emitAction({ type: ActionType.ChatResponsePart, turnId: this._turnId, @@ -9276,17 +9276,11 @@ export class CopilotAgentSession extends Disposable { if (this._shouldDropLateRootTurnEvent('assistant.message')) { return; } - if (isLastMessageChunk) { - const recorded = this._reasoningTiming.completeMessage(e.id, e.data.reasoningText, contentParentToolCallId); - if (!recorded && e.data.reasoningText) { - this._logService.trace(`[Copilot:${this.sessionId}] No complete observed reasoning interval for assistant message ${e.id}`); - } - } const markdownScope = contentParentToolCallId ?? ''; const state = this._getResponsePartState(contentParentToolCallId); const isEmptyFinalAnswer = isLastMessageChunk && e.data.phase === 'final_answer' && !e.data.content && !e.data.toolRequests?.length; // Fusion sends distinct complete chunks without preceding text deltas. - if (e.data.content && (isFusionMessage || !state?.markdownPartIds.has(markdownScope))) { + if (e.data.content && (isFusionMessage || (!state?.markdownPartIds.has(markdownScope) && !this._reasoningTiming.hasMarkdown(contentParentToolCallId)))) { const partId = generateUuid(); state?.markdownPartIds.set(markdownScope, partId); this._emitAction({ @@ -9295,8 +9289,6 @@ export class CopilotAgentSession extends Disposable { part: { kind: ResponsePartKind.Markdown, id: partId, content: e.data.content }, }, contentParentToolCallId); } else if (isEmptyFinalAnswer && !state?.markdownPartIds.has(markdownScope)) { - // An empty final answer still ends the open thinking section; later text and reasoning start new parts. - state?.reasoningPartIds.delete(markdownScope); this._emitAction({ type: ActionType.ChatResponsePart, turnId: this._turnId, @@ -9324,6 +9316,12 @@ export class CopilotAgentSession extends Disposable { // Wait for the full message boundary; clearing on an earlier tool delta would duplicate assembled markdown. this._beginToolCallRound(contentParentToolCallId); } + if (isLastMessageChunk) { + const recorded = this._reasoningTiming.completeMessage(e.id, e.data.reasoningText, e.data.content ?? '', contentParentToolCallId); + if (!recorded && e.data.reasoningText) { + this._logService.trace(`[Copilot:${this.sessionId}] No complete observed response layout for assistant message ${e.id}`); + } + } }; const renderCommittedFusionMessage = (e: SessionEventPayload<'assistant.message'>, phaseToolCallId: string): void => { const call = this._pendingFusionMessageChunks.accept(e, phaseToolCallId); @@ -10866,7 +10864,7 @@ export class CopilotAgentSession extends Disposable { if (this._shouldDropUnmappedSubagentEvent(e, 'assistant.reasoning_delta')) { return; } - this._emitReasoningDelta(e.data.deltaContent, e.data.reasoningId, this._parentToolCallIdForSubagentEvent(e)); + this._emitReasoningDelta(e.data.deltaContent, this._parentToolCallIdForSubagentEvent(e)); })); // Sync the AHP session config when the SDK's `currentMode` changes @@ -12031,8 +12029,6 @@ export class CopilotAgentSession extends Disposable { return; } this._reportedByokDroppedToolCount = droppedToolCount; - // Later parent reasoning belongs after this notice. - turn.reasoningPartIds.delete(''); this._emitAction({ type: ActionType.ChatResponsePart, turnId: turn.id, @@ -12370,7 +12366,6 @@ export class CopilotAgentSession extends Disposable { store.add(wrapper.onReasoning(e => { this._logService.trace(`[Copilot:${sessionId}] Reasoning: ${e.data.content.length} chars`); - this._reasoningTiming.finish(this._parentToolCallIdForSubagentEvent(e), e.data.reasoningId); })); store.add(wrapper.onTurnEnd(e => { diff --git a/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts b/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts index 87e03726d12b0..d510e1e63a6c6 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotReasoningTiming.ts @@ -5,77 +5,232 @@ import { Disposable } from '../../../../base/common/lifecycle.js'; import { StopWatch } from '../../../../base/common/stopwatch.js'; -import type { IReasoningTiming } from '../../common/sessionDataService.js'; +import type { ILogService } from '../../../log/common/log.js'; +import type { StoredAssistantResponsePart } from '../../common/sessionDataService.js'; import { ActionType, type ChatReasoningAction } from '../../common/state/sessionActions.js'; +import { ResponsePartKind, type MarkdownResponsePart, type ReasoningResponsePart, type ResponsePart } from '../../common/state/sessionState.js'; -interface IReasoningInterval { +interface IRecordedMessage { readonly turnId: string; - readonly startedAt: string; - readonly content: string[]; - duration: number; - active?: { readonly reasoningId: string; readonly partId: string; readonly startedAt: string; readonly clock: StopWatch }; + readonly responseId: string; + readonly parts: StoredAssistantResponsePart[]; } -/** Measures live fragments and associates their total with the SDK's durable assistant message. */ +interface IReasoningScope { + readonly turnId: string; + parts: StoredAssistantResponsePart[]; + readonly tools: Set; + active?: { + readonly partId: string; + readonly startedAt: string; + readonly clock: StopWatch; + readonly messages: Set; + persistable: boolean; + }; +} + +export interface IRecordedResponseParts { + readonly responseId: string; + readonly original: readonly ResponsePart[]; + readonly recorded: readonly StoredAssistantResponsePart[]; +} + +/** Measures contiguous reasoning output independently of SDK block and message boundaries. */ export class CopilotReasoningTiming extends Disposable { - private readonly _intervals = new Map(); + private readonly _scopes = new Map(); constructor( private readonly _emit: (action: ChatReasoningAction, parentToolCallId: string | undefined) => void, - private readonly _persist: (turnId: string, responseId: string, timing: IReasoningTiming) => void, + private readonly _persist: (turnId: string, responseId: string, parts: readonly StoredAssistantResponsePart[]) => void, ) { super(); } - activePartId(turnId: string, reasoningId: string, parentToolCallId: string | undefined): string | undefined { - const interval = this._intervals.get(parentToolCallId); - return interval?.turnId === turnId && interval.active?.reasoningId === reasoningId ? interval.active.partId : undefined; + activePartId(turnId: string, parentToolCallId: string | undefined): string | undefined { + const scope = this._scopes.get(parentToolCallId); + return scope?.turnId === turnId ? scope.active?.partId : undefined; } - start(turnId: string, reasoningId: string, partId: string, parentToolCallId: string | undefined): string { - this.finish(parentToolCallId); + start(turnId: string, partId: string, parentToolCallId: string | undefined): string { + const scope = this.getScope(turnId, parentToolCallId); const startedAt = new Date().toISOString(); - if (this._intervals.get(parentToolCallId)?.turnId !== turnId) { - this._intervals.set(parentToolCallId, { turnId, startedAt, content: [], duration: 0 }); - } - const interval = this._intervals.get(parentToolCallId)!; - interval.active = { reasoningId, partId, startedAt, clock: StopWatch.create() }; + scope.active = { partId, startedAt, clock: StopWatch.create(), messages: new Set(), persistable: true }; return startedAt; } append(content: string, parentToolCallId: string | undefined): void { - this._intervals.get(parentToolCallId)?.content.push(content); + const scope = this._scopes.get(parentToolCallId); + if (!scope?.active) { + throw new Error('Reasoning output has no active interval'); + } + const last = scope.parts.at(-1); + if (last?.kind === ResponsePartKind.Reasoning && last.id === scope.active.partId) { + last.content += content; + } else { + scope.parts.push({ kind: ResponsePartKind.Reasoning, id: scope.active.partId, content, startedAt: scope.active.startedAt }); + } + } + + markdown(turnId: string, partId: string, content: string, parentToolCallId: string | undefined): void { + this.finish(parentToolCallId); + const scope = this.getScope(turnId, parentToolCallId); + const last = scope.parts.at(-1); + if (last?.kind === ResponsePartKind.Markdown && last.id === partId) { + last.content += content; + } else { + scope.parts.push({ kind: ResponsePartKind.Markdown, id: partId, content }); + } + } + + toolCall(turnId: string, toolCallId: string, parentToolCallId: string | undefined): void { + const scope = this.getScope(turnId, parentToolCallId); + if (!scope.tools.has(toolCallId)) { + scope.tools.add(toolCallId); + this.finish(parentToolCallId); + scope.parts.push({ kind: ResponsePartKind.ToolCall, toolCallId }); + } + } + + hasMarkdown(parentToolCallId: string | undefined): boolean { + return this._scopes.get(parentToolCallId)?.parts.some(part => part.kind === ResponsePartKind.Markdown) ?? false; } - finish(parentToolCallId: string | undefined, reasoningId?: string): void { - const interval = this._intervals.get(parentToolCallId); - if (!interval?.active || (reasoningId !== undefined && reasoningId !== interval.active.reasoningId)) { + finish(parentToolCallId: string | undefined): void { + const scope = this._scopes.get(parentToolCallId); + const active = scope?.active; + if (!scope || !active) { return; } - const { partId, startedAt, clock } = interval.active; - const duration = Math.max(0, Math.round(clock.elapsed())); - interval.active = undefined; - interval.duration += duration; - this._emit({ type: ActionType.ChatReasoning, turnId: interval.turnId, partId, content: '', startedAt, duration }, parentToolCallId); + const duration = Math.max(0, Math.round(active.clock.elapsed())); + scope.active = undefined; + const finishParts = (parts: StoredAssistantResponsePart[]) => { + for (const part of parts) { + if (part.kind === ResponsePartKind.Reasoning && part.id === active.partId && active.persistable) { + part.duration = duration; + } + } + }; + finishParts(scope.parts); + for (const message of active.messages) { + finishParts(message.parts); + this.persist(message); + } + this._emit({ type: ActionType.ChatReasoning, turnId: scope.turnId, partId: active.partId, content: '', startedAt: active.startedAt, duration }, parentToolCallId); } - completeMessage(responseId: string, reasoningText: string | undefined, parentToolCallId: string | undefined): boolean { - this.finish(parentToolCallId); - const interval = this._intervals.get(parentToolCallId); - const recorded = interval !== undefined && !!reasoningText && interval.content.join('') === reasoningText; - if (recorded) { - this._persist(interval.turnId, responseId, { startedAt: interval.startedAt, duration: interval.duration }); + completeMessage(responseId: string, reasoningText: string | undefined, content: string, parentToolCallId: string | undefined): boolean { + const scope = this._scopes.get(parentToolCallId); + if (!scope || (!reasoningText && !content)) { + return false; } - this.clear(parentToolCallId); - return recorded; + const parts = scope.parts; + scope.parts = []; + const matches = parts.filter(part => part.kind === ResponsePartKind.Reasoning).map(part => part.content).join('') === (reasoningText ?? '') + && parts.filter(part => part.kind === ResponsePartKind.Markdown).map(part => part.content).join('') === content; + if (!matches) { + if (scope.active && parts.some(part => part.kind === ResponsePartKind.Reasoning && part.id === scope.active?.partId)) { + scope.active.persistable = false; + } + return false; + } + if (!parts.some(part => part.kind === ResponsePartKind.Reasoning)) { + return false; + } + const message = { turnId: scope.turnId, responseId, parts }; + if (scope.active && parts.some(part => part.kind === ResponsePartKind.Reasoning && part.id === scope.active?.partId)) { + scope.active.messages.add(message); + } + this.persist(message); + return true; } clear(parentToolCallId: string | undefined): void { - this._intervals.delete(parentToolCallId); + this._scopes.delete(parentToolCallId); + } + + private getScope(turnId: string, parentToolCallId: string | undefined): IReasoningScope { + let scope = this._scopes.get(parentToolCallId); + if (scope?.turnId !== turnId) { + scope = { turnId, parts: [], tools: new Set() }; + this._scopes.set(parentToolCallId, scope); + } + return scope; + } + + private persist(message: IRecordedMessage): void { + this._persist(message.turnId, message.responseId, message.parts.map(part => ({ ...part }))); } override dispose(): void { - this._intervals.clear(); + this._scopes.clear(); super.dispose(); } } + +/** Reconstructs recorded stream order while retaining the provider's canonical tool results. */ +export function restoreRecordedResponseParts(parts: readonly ResponsePart[], responses: readonly IRecordedResponseParts[], logService?: ILogService): ResponsePart[] { + if (!responses.length) { + return [...parts]; + } + const tools = new Map(parts.flatMap((part, index) => part.kind === ResponsePartKind.ToolCall ? [[part.toolCall.toolCallId, { part, index }] as const] : [])); + const replacements = new Map(); + const replaced = new Set(); + const movedTools = new Set(); + for (const response of responses) { + const anchor = response.original[0]; + const anchorIndex = parts.indexOf(anchor); + if (anchorIndex < 0) { + logService?.warn(`[Copilot] Recorded response ${response.responseId} has no history anchor`); + continue; + } + let sawText = false; + const replacement: ResponsePart[] = []; + for (const part of response.recorded) { + if (part.kind === ResponsePartKind.ToolCall) { + const tool = tools.get(part.toolCallId); + if (!tool) { + logService?.warn(`[Copilot] Recorded response ${response.responseId} references an unavailable tool call ${part.toolCallId}`); + } else if (!movedTools.has(part.toolCallId) && (sawText || tool.index > anchorIndex)) { + movedTools.add(part.toolCallId); + replacement.push(tool.part); + } + } else { + sawText = true; + replacement.push({ ...part }); + } + } + replacements.set(anchor, replacement); + for (const original of response.original) { + replaced.add(original); + } + } + + const result: ResponsePart[] = []; + const textParts = new Map(); + const append = (part: ResponsePart) => { + if (part.kind === ResponsePartKind.Markdown || part.kind === ResponsePartKind.Reasoning) { + const key = `${part.kind}:${part.id}`; + const existing = textParts.get(key); + if (existing) { + existing.content += part.content; + if (existing.kind === ResponsePartKind.Reasoning && part.kind === ResponsePartKind.Reasoning) { + existing.startedAt ??= part.startedAt; + existing.duration = part.duration ?? existing.duration; + } + return; + } + part = { ...part }; + textParts.set(key, part); + } + result.push(part); + }; + for (const part of parts) { + const replacement = replacements.get(part); + if (replacement) { + replacement.forEach(append); + } else if (!replaced.has(part) && !(part.kind === ResponsePartKind.ToolCall && movedTools.has(part.toolCall.toolCallId))) { + append(part); + } + } + return result; +} diff --git a/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts b/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts index e393724a867ae..8f7806b17c1f1 100644 --- a/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts +++ b/src/vs/platform/agentHost/node/copilot/mapSessionEvents.ts @@ -10,6 +10,7 @@ import { basename, isAbsolute, join } from '../../../../base/common/path.js'; import { basename as resourceBasename } from '../../../../base/common/resources.js'; import { hasKey, isString } from '../../../../base/common/types.js'; import { URI } from '../../../../base/common/uri.js'; +import { restoreRecordedResponseParts, type IRecordedResponseParts } from './copilotReasoningTiming.js'; import { generateUuid } from '../../../../base/common/uuid.js'; import { AgentSession, COPILOT_CLI_AGENT_PROVIDER_ID } from '../../common/agent.js'; import { stripRedundantCdPrefix } from '../../common/commandLineHelpers.js'; @@ -342,6 +343,7 @@ interface ITurnBuilder { waitingStartedAt: string | undefined; waitingDuration: number; readonly responseParts: ResponsePart[]; + readonly recordedResponses: IRecordedResponseParts[]; imageGenerationSdkTurnId?: string; usage: UsageInfo | undefined; /** Tool starts seen but not yet completed in this turn, keyed by toolCallId. */ @@ -349,6 +351,7 @@ interface ITurnBuilder { } export interface IMapSessionEventsOptions { + readonly logService?: ILogService; readonly workingDirectory?: URI; /** Known client tool implementations, used to distinguish their inputs from native SDK tools. */ readonly clientToolNames?: ReadonlySet; @@ -365,7 +368,7 @@ function newTurnBuilder(id: string, text: string, options?: { attachments?: Mess ...(options?.model ? { model: options.model } : {}), ...(options?.agent ? { agent: options.agent } : {}), }; - return { id, message, startedAt: options?.startedAt, lastEventAt: options?.startedAt, waitingStartedAt: undefined, waitingDuration: 0, responseParts: [], usage: undefined, pendingTools: new Map() }; + return { id, message, startedAt: options?.startedAt, lastEventAt: options?.startedAt, waitingStartedAt: undefined, waitingDuration: 0, responseParts: [], recordedResponses: [], usage: undefined, pendingTools: new Map() }; } /** Reads the SDK envelope's ISO 8601 `timestamp`, or `undefined` when missing or unparseable. */ @@ -438,7 +441,7 @@ function makeToolStartInfo(toolName: string, rawArguments: unknown, parentToolCa } /** Seals a turn builder into a {@link Turn}, deriving `duration` from its first and last event timestamps. */ -function finalizeTurn(builder: ITurnBuilder, state: TurnState): Turn { +function finalizeTurn(builder: ITurnBuilder, state: TurnState, logService?: ILogService): Turn { const startedAtMs = builder.startedAt === undefined ? undefined : Date.parse(builder.startedAt); const endedAtMs = builder.lastEventAt === undefined ? undefined : Date.parse(builder.lastEventAt); const duration = startedAtMs !== undefined && endedAtMs !== undefined && Number.isFinite(startedAtMs) && Number.isFinite(endedAtMs) @@ -449,7 +452,7 @@ function finalizeTurn(builder: ITurnBuilder, state: TurnState): Turn { ...(builder.startedAt !== undefined ? { startedAt: builder.startedAt } : {}), ...(duration !== undefined ? { duration } : {}), message: builder.message, - responseParts: builder.responseParts, + responseParts: restoreRecordedResponseParts(builder.responseParts, builder.recordedResponses, logService), usage: builder.usage, state, }; @@ -481,7 +484,7 @@ export async function mapSessionEvents( const workingDirectory = options?.workingDirectory; let currentModel = options?.model; let currentAgent = options?.agent; - const reasoningTimings = await db?.getReasoningTimings(); + const recordedResponses = await db?.getAssistantResponseParts(); // First pass: collect tool-arg info and identify edit tool calls so we // can batch-load their stored file edits before the second pass needs // them at `tool.execution_complete` time. We also build the @@ -677,7 +680,7 @@ export async function mapSessionEvents( if (!parentBuilder) { return; } - turns.push(finalizeTurn(parentBuilder, parentTurnState)); + turns.push(finalizeTurn(parentBuilder, parentTurnState, options?.logService)); parentBuilder = undefined; parentTurnState = TurnState.Cancelled; parentTurnTerminated = false; @@ -698,7 +701,7 @@ export async function mapSessionEvents( return; } const list = subagentTurns.get(parentToolCallId) ?? []; - list.push(finalizeTurn(builder, state)); + list.push(finalizeTurn(builder, state, options?.logService)); subagentTurns.set(parentToolCallId, list); }; @@ -932,21 +935,32 @@ export async function mapSessionEvents( pendingSkillBuilder = undefined; touch(builder); } + const original: ResponsePart[] = []; if (reasoningText) { - builder.responseParts.push({ + original.push({ kind: ResponsePartKind.Reasoning, id: generateUuid(), content: reasoningText, - ...reasoningTimings?.get(e.id), }); } if (content) { - builder.responseParts.push({ + original.push({ kind: ResponsePartKind.Markdown, id: generateUuid(), content, }); } + builder.responseParts.push(...original); + const recorded = recordedResponses?.get(e.id); + if (recorded) { + const matches = recorded.filter(part => part.kind === ResponsePartKind.Reasoning).map(part => part.content).join('') === (reasoningText ?? '') + && recorded.filter(part => part.kind === ResponsePartKind.Markdown).map(part => part.content).join('') === content; + if (matches && original.length) { + builder.recordedResponses.push({ responseId: e.id, original, recorded }); + } else { + options?.logService?.warn(`[Copilot] Recorded response parts no longer match assistant message ${e.id}`); + } + } if (!parentToolCallId && builder === parentBuilder && !parentTurnTerminated) { parentTurnState = hasToolRequests ? TurnState.Cancelled : TurnState.Complete; } @@ -1141,7 +1155,7 @@ export async function mapSessionEvents( } flushParent(); if (pendingSkillBuilder) { - turns.push(finalizeTurn(pendingSkillBuilder, TurnState.Cancelled)); + turns.push(finalizeTurn(pendingSkillBuilder, TurnState.Cancelled, options?.logService)); } for (const parentToolCallId of [...subagentBuilders.keys()]) { flushSubagent(parentToolCallId); diff --git a/src/vs/platform/agentHost/node/sessionDatabase.ts b/src/vs/platform/agentHost/node/sessionDatabase.ts index b288bbb12a6c0..69b2f363838e2 100644 --- a/src/vs/platform/agentHost/node/sessionDatabase.ts +++ b/src/vs/platform/agentHost/node/sessionDatabase.ts @@ -6,10 +6,10 @@ import * as fs from 'fs'; import { Sequencer, SequencerByKey } from '../../../base/common/async.js'; import type { Database, RunResult } from '@vscode/sqlite3'; -import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReasoningTiming, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../common/sessionDataService.js'; +import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord, type StoredAssistantResponsePart } from '../common/sessionDataService.js'; import { dirname } from '../../../base/common/path.js'; import { URI } from '../../../base/common/uri.js'; -import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, type Message } from '../common/state/sessionState.js'; +import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, ResponsePartKind, type Message } from '../common/state/sessionState.js'; import { configureSqliteJournal } from './agentHostSqliteJournal.js'; /** @@ -270,8 +270,32 @@ export const sessionDatabaseMigrations: readonly ISessionDatabaseMigration[] = [ duration INTEGER NOT NULL CHECK(duration >= 0) )`, }, + { + version: 18, + sql: `CREATE TABLE IF NOT EXISTS assistant_response_parts ( + response_id TEXT PRIMARY KEY NOT NULL, + turn_id TEXT NOT NULL REFERENCES turns(id) ON DELETE CASCADE, + parts TEXT NOT NULL + )`, + }, ]; +function isStoredAssistantResponsePart(part: unknown): part is StoredAssistantResponsePart { + if (!part || typeof part !== 'object' || !('kind' in part)) { + return false; + } + if (part.kind === ResponsePartKind.ToolCall) { + return 'toolCallId' in part && typeof part.toolCallId === 'string'; + } + if ((part.kind !== ResponsePartKind.Markdown && part.kind !== ResponsePartKind.Reasoning) + || !('id' in part) || typeof part.id !== 'string' || !('content' in part) || typeof part.content !== 'string') { + return false; + } + return part.kind === ResponsePartKind.Markdown + || ((!('startedAt' in part) || part.startedAt === undefined || (typeof part.startedAt === 'string' && Number.isFinite(Date.parse(part.startedAt)))) + && (!('duration' in part) || part.duration === undefined || (typeof part.duration === 'number' && Number.isSafeInteger(part.duration) && part.duration >= 0))); +} + // ---- Promise wrappers around callback-based @vscode/sqlite3 API ----------- function dbExec(db: Database, sql: string): Promise { @@ -773,28 +797,33 @@ export class SessionDatabase implements ISessionDatabase { }); } - setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise { + setAssistantResponseParts(turnId: string, responseId: string, parts: readonly StoredAssistantResponsePart[]): Promise { + const valid = parts.every(isStoredAssistantResponsePart); + const serialized = JSON.stringify(parts); return this._mutate(async db => { - if (!Number.isFinite(Date.parse(timing.startedAt)) || !Number.isSafeInteger(timing.duration) || timing.duration < 0) { - throw new Error('Invalid reasoning timing'); + if (!valid) { + throw new Error('Invalid assistant response parts'); } await dbRun(db, 'INSERT OR IGNORE INTO turns (id) VALUES (?)', [turnId]); - await dbRun(db, 'INSERT OR REPLACE INTO reasoning_timing (response_id, turn_id, started_at, duration) VALUES (?, ?, ?, ?)', - [responseId, turnId, timing.startedAt, timing.duration]); + await dbRun(db, 'INSERT OR REPLACE INTO assistant_response_parts (response_id, turn_id, parts) VALUES (?, ?, ?)', + [responseId, turnId, serialized]); }); } - async getReasoningTimings(): Promise> { + async getAssistantResponseParts(): Promise> { await this.whenIdle(); const db = await this._ensureDb(); - const rows = await dbAll(db, 'SELECT response_id, started_at, duration FROM reasoning_timing', []); - const result = new Map(); + const rows = await dbAll(db, 'SELECT response_id, parts FROM assistant_response_parts', []); + const result = new Map(); for (const row of rows) { - if (typeof row.response_id !== 'string' || typeof row.started_at !== 'string' || !Number.isFinite(Date.parse(row.started_at)) - || typeof row.duration !== 'number' || !Number.isSafeInteger(row.duration) || row.duration < 0) { - throw new Error('Invalid persisted reasoning timing'); + if (typeof row.response_id !== 'string' || typeof row.parts !== 'string') { + throw new Error('Invalid persisted assistant response parts'); + } + const parts: unknown = JSON.parse(row.parts); + if (!Array.isArray(parts) || !parts.every(isStoredAssistantResponsePart)) { + throw new Error(`Invalid persisted assistant response parts for ${row.response_id}`); } - result.set(row.response_id, { startedAt: row.started_at, duration: row.duration }); + result.set(row.response_id, parts); } return result; } @@ -1643,6 +1672,7 @@ export class SessionDatabase implements ISessionDatabase { for (const [oldId, newId] of mapping) { await dbRun(db, 'UPDATE turn_usage SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); await dbRun(db, 'UPDATE reasoning_timing SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); + await dbRun(db, 'UPDATE assistant_response_parts SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); await dbRun(db, 'UPDATE turn_delegation SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); await dbRun(db, 'UPDATE turn_workspace_transition SET turn_id = ? WHERE turn_id = ?', [newId, oldId]); } diff --git a/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts b/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts index 8803d317f325e..7f5b367e8c6e9 100644 --- a/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts +++ b/src/vs/platform/agentHost/test/common/sessionTestHelpers.ts @@ -9,7 +9,7 @@ import { URI } from '../../../../base/common/uri.js'; import { Emitter, Event } from '../../../../base/common/event.js'; import { constObservable } from '../../../../base/common/observable.js'; import type { IDetailedDiffResult, IDiffComputeService, IDiffCountResult, IDiffHunksResult } from '../../common/diffComputeService.js'; -import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReasoningTiming, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionDataService, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord } from '../../common/sessionDataService.js'; +import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IFileEditContent, type IFileEditRecord, type IPersistedTurnRecord, type IReviewedFileRecord, type ISessionCatalogSyncAcknowledgement, type ISessionCatalogSyncPendingSnapshot, type ISessionCatalogSyncSnapshot, type ISessionDatabase, type ISessionDataService, type ISessionRowsWatermark, type IToolResultResource, type SessionCatalogSyncTransitionResult, type SessionCatalogSyncWriteResult, type SessionCatalogSyncWriteValidator, SESSION_FOREIGN_TURN_IDS_METADATA_KEY, SESSION_ROW_OWNER_CHAT_METADATA_KEY, type ITurnCheckpointRecord, type StoredAssistantResponsePart } from '../../common/sessionDataService.js'; import type { IAgentHostCheckpointService } from '../../common/agentHostCheckpointService.js'; import type { IAgentHostGitStateService } from '../../common/agentHostGitStateService.js'; import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, type ISessionGitHubState, type Message } from '../../common/state/sessionState.js'; @@ -49,7 +49,7 @@ export class TestSessionDatabase implements ISessionDatabase { private readonly _turns = new Set(); private readonly _persistedTurns = new Map(); private readonly _turnUsages = new Map(); - private readonly _reasoningTimings = new Map(); + private readonly _assistantResponseParts = new Map(); private readonly _turnDelegations = new Map(); private readonly _turnWorkspaceTransitions = new Map(); private readonly _turnEventIds = new Map(); @@ -78,7 +78,7 @@ export class TestSessionDatabase implements ISessionDatabase { this._turnDelegations.delete(turnId); this._turnWorkspaceTransitions.delete(turnId); this._turnEventIds.delete(turnId); - this._deleteToolResultsForTurns(new Set([turnId])); + this._deleteTurnContent(new Set([turnId])); for (let i = this._edits.length - 1; i >= 0; i--) { if (this._edits[i].turnId === turnId) { this._edits.splice(i, 1); @@ -363,12 +363,14 @@ export class TestSessionDatabase implements ISessionDatabase { async getTurnUsages(): Promise> { return new Map(this._turnUsages); } - async setReasoningTiming(turnId: string, responseId: string, timing: IReasoningTiming): Promise { + async setAssistantResponseParts(turnId: string, responseId: string, parts: readonly StoredAssistantResponsePart[]): Promise { this._turns.add(turnId); - this._reasoningTimings.set(responseId, timing); + this._assistantResponseParts.set(responseId, { turnId, parts: parts.map(part => ({ ...part })) }); } - async getReasoningTimings(): Promise> { return new Map(this._reasoningTimings); } + async getAssistantResponseParts(): Promise> { + return new Map([...this._assistantResponseParts].map(([id, value]) => [id, value.parts])); + } async setTurnDelegation(turnId: string, delegation: string): Promise { this._turns.add(turnId); @@ -423,7 +425,7 @@ export class TestSessionDatabase implements ISessionDatabase { const index = turnIds.indexOf(turnId); if (index >= 0) { const prunedTurnIds = new Set(turnIds.slice(index)); - this._deleteToolResultsForTurns(prunedTurnIds); + this._deleteTurnContent(prunedTurnIds); for (const prunedTurnId of prunedTurnIds) { this._turns.delete(prunedTurnId); this._persistedTurns.delete(prunedTurnId); @@ -437,7 +439,7 @@ export class TestSessionDatabase implements ISessionDatabase { const index = turnIds.indexOf(turnId); if (index >= 0) { const prunedTurnIds = new Set(turnIds.slice(index + 1)); - this._deleteToolResultsForTurns(prunedTurnIds); + this._deleteTurnContent(prunedTurnIds); for (const prunedTurnId of prunedTurnIds) { this._turns.delete(prunedTurnId); this._persistedTurns.delete(prunedTurnId); @@ -448,7 +450,7 @@ export class TestSessionDatabase implements ISessionDatabase { async deleteAllTurns(): Promise { this.deleteAllTurnsCalls++; this._turns.clear(); - this._reasoningTimings.clear(); + this._assistantResponseParts.clear(); this._edits.length = 0; this._turnDelegations.clear(); this._turnWorkspaceTransitions.clear(); @@ -577,10 +579,23 @@ export class TestSessionDatabase implements ISessionDatabase { this._toolResultResources.set(toolCallId, { ...resources, turnId: remappedTurnId }); } } + for (const [responseId, response] of this._assistantResponseParts) { + const turnId = mapping.get(response.turnId); + if (turnId) { + this._assistantResponseParts.set(responseId, { ...response, turnId }); + } else { + this._assistantResponseParts.delete(responseId); + } + } this._deleteWorkspaceTransitionMarkerIfEmpty(); } - private _deleteToolResultsForTurns(turnIds: ReadonlySet): void { + private _deleteTurnContent(turnIds: ReadonlySet): void { + for (const [responseId, response] of this._assistantResponseParts) { + if (turnIds.has(response.turnId)) { + this._assistantResponseParts.delete(responseId); + } + } for (const [toolCallId, output] of this._terminalOutputs) { if (turnIds.has(output.turnId)) { this._terminalOutputs.delete(toolCallId); diff --git a/src/vs/platform/agentHost/test/node/README.md b/src/vs/platform/agentHost/test/node/README.md index 1821c4d3cf357..05754d9922006 100644 --- a/src/vs/platform/agentHost/test/node/README.md +++ b/src/vs/platform/agentHost/test/node/README.md @@ -14,11 +14,13 @@ The protocol and E2E folders contain their own running and authoring instruction ## Reasoning timing -AHP reasoning parts carry optional producer-owned `startedAt` and `duration` fields. Timing-only `chat/reasoning` updates finish a live interval before subsequent response content or the turn's terminal action. Clients retain those values across snapshots and history replay rather than measuring replay or comparing the host's clock with their own. +AHP reasoning parts carry optional producer-owned `startedAt` and `duration` fields for one contiguous run of thinking output. A run starts at its first nonempty reasoning text and ends at the next markdown or tool-call part, or at turn termination. SDK reasoning IDs, reasoning-complete events, full-message boundaries, and sideband notifications do not split a run. Timing-only `chat/reasoning` updates finish the run before publishing the following content or terminal action. -Copilot measures streamed reasoning with a monotonic clock and stores its total against the durable assistant-message event id in the session database's `reasoning_timing` table. Split fragments contribute only their observed reasoning time; tool execution and gaps between fragments are excluded. Writes follow the owning turn through fork remapping and pruning. Restored provider responses without a complete recorded interval remain untimed; this does not retroactively estimate older sessions or add timing capture to other providers. +Copilot measures runs with a monotonic clock and stores the observed ordering of reasoning, markdown, and tool references against durable assistant-message event IDs in `assistant_response_parts`. A run may span SDK messages; its fragments share one ID and are updated with the same final duration, then reassembled without summing it during replay. Conversely, two runs separated by markdown or a tool retain separate IDs and durations even when the SDK saves one message containing both. Native tool results are retained and placed at the recorded boundaries. The projection is used only when its text still matches the provider transcript. -`copilotReasoningTiming.test.ts` covers fragment measurement and a real database close/reopen followed by provider history reconstruction. `copilotAgentSession.test.ts`, `sessionDatabase.test.ts`, and the workbench chat adapter/model/thinking-content tests cover producer wiring, storage, reconnects, serialization, and the visible and accessible "Thought for 45s" label. +Recorded parts follow turn remapping and pruning. The earlier draft's aggregate `reasoning_timing` rows are not reinterpreted as per-run timings. Unknown history and unfinished runs remain untimed rather than counting time while the host is stopped. This does not add capture to other providers or estimate older history. + +Single-run thinking headers use labels such as "Thought for 5s". Conversation grouping remains available, but its expanded reasoning rows show their individual durations instead of a group-wide sum. `copilotReasoningTiming.test.ts` covers 5s/12s markdown/tool boundaries through a real database restart and a single run spanning SDK messages. The provider, model, database, and renderer tests cover live boundaries, identity, migration, serialization, grouped display, and accessible text. ## Mission Control session configuration diff --git a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts index 841caa3ad4765..1dca6357d9689 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgentSession.test.ts @@ -9783,7 +9783,7 @@ suite('CopilotAgentSession', () => { }); for (const phase of ['commentary', 'final_answer']) { - test(`marks only an empty final answer as a section boundary without claiming the markdown scope (${phase})`, async () => { + test(`retains empty final-answer notices without reusing reasoning across markdown (${phase})`, async () => { const { session, mockSession, signals } = await createAgentSession(disposables); session.resetTurnState('turn-parent'); mockSession.fire('assistant.turn_start', { turnId: 'sdk-parent' }); @@ -9804,11 +9804,12 @@ suite('CopilotAgentSession', () => { } return [{ kind: part.kind, content: part.kind === ResponsePartKind.Markdown || part.kind === ResponsePartKind.Reasoning ? part.content : undefined }]; } - return action.type === ActionType.ChatDelta || action.type === ActionType.ChatReasoning ? [{ kind: action.type, content: action.content }] : []; + return action.type === ActionType.ChatDelta || (action.type === ActionType.ChatReasoning && action.content) ? [{ kind: action.type, content: action.content }] : []; }); assert.deepStrictEqual({ parts, + timingUpdates: getActions(signals).filter(action => action.type === ActionType.ChatReasoning && action.duration !== undefined).length, parentCompleted: getActions(signals).some(action => action.type === ActionType.ChatTurnComplete), childCompleted: signals.some(signal => signal.kind === 'subagent_completed'), }, { @@ -9822,8 +9823,9 @@ suite('CopilotAgentSession', () => { : [ { kind: ResponsePartKind.Reasoning, content: 'Assessing' }, { kind: ResponsePartKind.Markdown, content: 'Later text' }, - { kind: ActionType.ChatReasoning, content: 'Later reasoning' }, + { kind: ResponsePartKind.Reasoning, content: 'Later reasoning' }, ], + timingUpdates: 1, parentCompleted: false, childCompleted: false, }); @@ -16663,7 +16665,7 @@ Use the attached image as context. ]); }); - test('completion notifications split parent reasoning without splitting running subagent reasoning', async () => { + test('completion notifications do not split contiguous parent or child reasoning', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); session.resetTurnState('turn-active'); mockSession.fire('subagent.started', { @@ -16705,12 +16707,12 @@ Use the attached image as context. { kind: ResponsePartKind.Reasoning, scope: 'parent', content: 'Before notification' }, { kind: ResponsePartKind.Reasoning, scope: 'task-running', content: 'Child reasoning' }, { kind: ResponsePartKind.SystemNotification, scope: 'parent', content: 'Background agent `Completed reviewer` is complete' }, - { kind: ResponsePartKind.Reasoning, scope: 'parent', content: 'After notification' }, + { kind: 'delta', scope: 'parent', content: 'After notification' }, { kind: 'delta', scope: 'parent', content: ' continued' }, { kind: 'delta', scope: 'task-running', content: ' still running' }, ], - parentReasoningParts: 2, - timingScopes: ['parent'], + parentReasoningParts: 1, + timingScopes: [], }); }); @@ -23683,15 +23685,16 @@ Use the attached image as context. const finalTiming = actions.flatMap(action => action.type === ActionType.ChatReasoning && action.duration !== undefined ? [action] : [])[0]; const timingIndex = actions.indexOf(finalTiming); const answerIndex = actions.findIndex(action => action.type === ActionType.ChatResponsePart && action.part.kind === ResponsePartKind.Markdown); - const recorded = await database.getReasoningTimings(); + const recorded = await database.getAssistantResponseParts(); + const recordedReasoning = recorded.get('durable-response')?.find(part => part.kind === ResponsePartKind.Reasoning); assert.deepStrictEqual({ duration: finalTiming?.duration, partIdMatches: finalTiming?.partId === reasoning?.id, publishedBeforeAnswer: timingIndex >= 0 && timingIndex < answerIndex, recorded: [...recorded.keys()], - recordedDuration: recorded.get('durable-response')?.duration, - startMatches: recorded.get('durable-response')?.startedAt === reasoning?.startedAt, + recordedDuration: recordedReasoning?.duration, + startMatches: recordedReasoning?.startedAt === reasoning?.startedAt, }, { duration: 45_000, partIdMatches: true, @@ -23705,6 +23708,43 @@ Use the attached image as context. } }); + test('SDK reasoning and message completion do not end contiguous thinking output', async () => { + const database = new TestSessionDatabase(); + const { session, mockSession, signals } = await createAgentSession(disposables, { sessionDatabase: database }); + const elapsed = stub(StopWatch.prototype, 'elapsed').returns(45_000); + try { + session.resetTurnState('host-turn'); + mockSession.fire('assistant.reasoning_delta', { reasoningId: 'sdk-first', deltaContent: 'First' }); + mockSession.fire('assistant.reasoning', { reasoningId: 'sdk-first', content: 'First' }); + mockSession.fire('assistant.message', { messageId: 'message-first', content: '', reasoningText: 'First' }, { id: 'durable-first' }); + mockSession.fire('assistant.reasoning_delta', { reasoningId: 'sdk-second', deltaContent: 'Second' }); + mockSession.fire('assistant.reasoning', { reasoningId: 'sdk-second', content: 'Second' }); + mockSession.fire('assistant.message', { messageId: 'message-second', content: '', reasoningText: 'Second' }, { id: 'durable-second' }); + const beforeBoundary = signals.filter(signal => signal.kind === 'action' && signal.action.type === ActionType.ChatReasoning && signal.action.duration !== undefined).length; + mockSession.fire('assistant.message_delta', { messageId: 'answer', deltaContent: 'Done' }); + const parts = signals.flatMap(signal => signal.kind === 'action' && signal.action.type === ActionType.ChatResponsePart && signal.action.part.kind === ResponsePartKind.Reasoning ? [signal.action.part] : []); + const durations = signals.flatMap(signal => signal.kind === 'action' && signal.action.type === ActionType.ChatReasoning && signal.action.duration !== undefined ? [signal.action.duration] : []); + const recorded = await database.getAssistantResponseParts(); + + assert.deepStrictEqual({ + beforeBoundary, + reasoningParts: parts.length, + durations, + recorded: [...recorded].map(([responseId, value]) => ({ responseId, runs: value.flatMap(part => part.kind === ResponsePartKind.Reasoning ? [{ sameRun: part.id === parts[0].id, duration: part.duration }] : []) })), + }, { + beforeBoundary: 0, + reasoningParts: 1, + durations: [45_000], + recorded: [ + { responseId: 'durable-first', runs: [{ sameRun: true, duration: 45_000 }] }, + { responseId: 'durable-second', runs: [{ sameRun: true, duration: 45_000 }] }, + ], + }); + } finally { + elapsed.restore(); + } + }); + test('reasoning delta after tool_start starts a new reasoning response part', async () => { const { session, mockSession, signals } = await createAgentSession(disposables); session.resetTurnState('turn-1'); diff --git a/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts b/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts index a0021f7fafe56..f2877b789371f 100644 --- a/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotReasoningTiming.test.ts @@ -11,133 +11,235 @@ import { join } from '../../../../base/common/path.js'; import { StopWatch } from '../../../../base/common/stopwatch.js'; import { URI } from '../../../../base/common/uri.js'; import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../base/test/common/utils.js'; -import type { IReasoningTiming } from '../../common/sessionDataService.js'; -import { ActionType, type ChatReasoningAction } from '../../common/state/sessionActions.js'; +import type { StoredAssistantResponsePart } from '../../common/sessionDataService.js'; +import type { ChatReasoningAction } from '../../common/state/sessionActions.js'; import { ResponsePartKind } from '../../common/state/sessionState.js'; import { CopilotReasoningTiming } from '../../node/copilot/copilotReasoningTiming.js'; import { mapSessionEvents } from '../../node/copilot/mapSessionEvents.js'; import { SessionDatabase } from '../../node/sessionDatabase.js'; -import { toSessionEvents } from './copilotTestEvents.js'; +import { toSessionEvents, type ISessionEvent } from './copilotTestEvents.js'; suite('CopilotReasoningTiming', () => { const store = ensureNoDisposablesAreLeakedInTestSuite(); - let elapsed = 0; + let clock: ReturnType; setup(() => { - elapsed = 0; - sinon.useFakeTimers({ now: 1000, toFake: ['Date'] }); - sinon.stub(StopWatch.prototype, 'elapsed').callsFake(() => elapsed); + clock = sinon.useFakeTimers({ now: 1000, toFake: ['Date'] }); + sinon.stub(StopWatch, 'create').callsFake(() => new StopWatch(false)); }); teardown(() => sinon.restore()); function createTiming() { const actions: { action: ChatReasoningAction; parentToolCallId: string | undefined }[] = []; - const recorded: { turnId: string; responseId: string; timing: IReasoningTiming }[] = []; + const recorded = new Map(); const timing = store.add(new CopilotReasoningTiming( (action, parentToolCallId) => actions.push({ action, parentToolCallId }), - (turnId, responseId, value) => recorded.push({ turnId, responseId, timing: value }), + (_turnId, responseId, parts) => recorded.set(responseId, parts), )); return { timing, actions, recorded }; } - test('records 45 seconds against the durable assistant message without a reasoning completion event', () => { + test('keeps 5s and 12s runs separate within one SDK message', () => { const { timing, actions, recorded } = createTiming(); - timing.start('turn', 'sdk-reasoning', 'part', undefined); - timing.append('Thinking', undefined); - elapsed = 45_000; - timing.completeMessage('assistant-event', 'Thinking', undefined); - timing.finish(undefined); - - assert.deepStrictEqual({ actions, recorded }, { - actions: [{ parentToolCallId: undefined, action: { type: ActionType.ChatReasoning, turnId: 'turn', partId: 'part', content: '', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 } }], - recorded: [{ turnId: 'turn', responseId: 'assistant-event', timing: { startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 } }], + timing.start('turn', 'first', undefined); + timing.append('First', undefined); + clock.tick(5000); + timing.markdown('turn', 'between', 'Between', undefined); + clock.tick(20_000); + timing.start('turn', 'second', undefined); + timing.append('Second', undefined); + clock.tick(12_000); + timing.markdown('turn', 'answer', 'Done', undefined); + timing.completeMessage('message', 'FirstSecond', 'BetweenDone', undefined); + + assert.deepStrictEqual({ + durations: actions.map(({ action }) => ({ id: action.partId, duration: action.duration })), + parts: recorded.get('message'), + }, { + durations: [{ id: 'first', duration: 5000 }, { id: 'second', duration: 12_000 }], + parts: [ + { kind: ResponsePartKind.Reasoning, id: 'first', content: 'First', startedAt: '1970-01-01T00:00:01.000Z', duration: 5000 }, + { kind: ResponsePartKind.Markdown, id: 'between', content: 'Between' }, + { kind: ResponsePartKind.Reasoning, id: 'second', content: 'Second', startedAt: '1970-01-01T00:00:26.000Z', duration: 12_000 }, + { kind: ResponsePartKind.Markdown, id: 'answer', content: 'Done' }, + ], }); }); - test('sums split reasoning fragments without including the gaps or timing another chat', () => { + test('SDK messages do not end a run and completed timing updates earlier message fragments', () => { const { timing, actions, recorded } = createTiming(); - timing.start('turn', 'reasoning-1', 'first', undefined); + timing.start('turn', 'run', undefined); timing.append('First', undefined); - timing.start('turn', 'child-reasoning', 'child', 'tool'); - timing.append('Child', 'tool'); - elapsed = 30_000; - timing.finish(undefined); - elapsed = 1500; - timing.completeMessage('child-message', 'Child', 'tool'); - timing.start('turn', 'reasoning-2', 'second', undefined); - timing.append(' second', undefined); - elapsed = 15_000; - timing.completeMessage('parent-message', 'First second', undefined); + clock.tick(5000); + timing.completeMessage('message-1', 'First', '', undefined); + const unfinished = recorded.get('message-1'); + const actionCountAtMessageBoundary = actions.length; + clock.tick(7000); + timing.append('Second', undefined); + clock.tick(12_000); + timing.markdown('turn', 'answer', 'Done', undefined); + timing.completeMessage('message-2', 'Second', 'Done', undefined); assert.deepStrictEqual({ - fragments: actions.map(({ action, parentToolCallId }) => ({ part: action.partId, duration: action.duration, parentToolCallId })), - totals: recorded.map(record => ({ response: record.responseId, duration: record.timing.duration })), + actionCountAtMessageBoundary, + unfinished, + durations: actions.map(({ action }) => action.duration), + parts: [...recorded.values()].flat().filter(part => part.kind === ResponsePartKind.Reasoning), }, { - fragments: [ - { part: 'first', duration: 30_000, parentToolCallId: undefined }, - { part: 'child', duration: 1500, parentToolCallId: 'tool' }, - { part: 'second', duration: 15_000, parentToolCallId: undefined }, + actionCountAtMessageBoundary: 0, + unfinished: [{ kind: ResponsePartKind.Reasoning, id: 'run', content: 'First', startedAt: '1970-01-01T00:00:01.000Z' }], + durations: [24_000], + parts: [ + { kind: ResponsePartKind.Reasoning, id: 'run', content: 'First', startedAt: '1970-01-01T00:00:01.000Z', duration: 24_000 }, + { kind: ResponsePartKind.Reasoning, id: 'run', content: 'Second', startedAt: '1970-01-01T00:00:01.000Z', duration: 24_000 }, ], - totals: [{ response: 'child-message', duration: 1500 }, { response: 'parent-message', duration: 45_000 }], }); }); - test('preserves zero but does not invent timing for unobserved, mismatched, or interrupted reasoning', () => { + test('parent and subagent runs stop independently', () => { + const { timing, actions } = createTiming(); + timing.start('turn', 'parent', undefined); + timing.append('Parent', undefined); + clock.tick(1000); + timing.start('turn', 'child', 'tool'); + timing.append('Child', 'tool'); + clock.tick(2000); + timing.completeMessage('child-message', 'Child', '', 'tool'); + clock.tick(3000); + timing.markdown('turn', 'parent-answer', 'Done', undefined); + clock.tick(4000); + timing.toolCall('turn', 'child-tool', 'tool'); + + assert.deepStrictEqual(actions.map(({ action, parentToolCallId }) => ({ id: action.partId, duration: action.duration, parentToolCallId })), [ + { id: 'parent', duration: 6000, parentToolCallId: undefined }, + { id: 'child', duration: 9000, parentToolCallId: 'tool' }, + ]); + }); + + test('preserves zero and leaves interrupted or mismatched recordings untimed', () => { const { timing, recorded } = createTiming(); - const unobserved = timing.completeMessage('unobserved', 'Thinking', undefined); - timing.start('turn', 'sdk', 'part', undefined); - timing.append('Thinking', undefined); - const zero = timing.completeMessage('zero', 'Thinking', undefined); - timing.start('turn', 'sdk-next', 'next', undefined); - timing.append('Observed prefix', undefined); - const mismatched = timing.completeMessage('mismatch', 'Different full response', undefined); - timing.start('turn', 'sdk-interrupted', 'interrupted', undefined); + timing.start('turn', 'zero', undefined); + timing.append('Immediate', undefined); + timing.markdown('turn', 'answer', 'Done', undefined); + timing.completeMessage('zero-message', 'Immediate', 'Done', undefined); + timing.start('turn', 'interrupted', undefined); timing.append('Partial', undefined); + timing.completeMessage('partial-message', 'Partial', '', undefined); timing.clear(undefined); - const interrupted = timing.completeMessage('interrupted', 'Partial', undefined); + clock.tick(60_000); + const unobserved = timing.completeMessage('old-message', 'Old history', '', undefined); + timing.start('turn', 'mismatch', undefined); + timing.append('Observed prefix', undefined); + const mismatch = timing.completeMessage('mismatch-message', 'Different content', '', undefined); + timing.append('Tail', undefined); + timing.markdown('turn', 'tail-answer', 'Done', undefined); + timing.completeMessage('tail-message', 'Tail', 'Done', undefined); - assert.deepStrictEqual({ unobserved, zero, mismatched, interrupted, recorded }, { - unobserved: false, zero: true, mismatched: false, interrupted: false, - recorded: [{ turnId: 'turn', responseId: 'zero', timing: { startedAt: '1970-01-01T00:00:01.000Z', duration: 0 } }], + assert.deepStrictEqual({ + unobserved, mismatch, + recorded: [...recorded].map(([id, parts]) => ({ id, durations: parts.flatMap(part => part.kind === ResponsePartKind.Reasoning ? [part.duration] : []) })), + }, { + unobserved: false, mismatch: false, + recorded: [ + { id: 'zero-message', durations: [0] }, + { id: 'partial-message', durations: [undefined] }, + { id: 'tail-message', durations: [undefined] }, + ], }); }); - test('restores timing after closing and reopening the database without timing identical historical text', async () => { - const directory = await fs.mkdtemp(join(tmpdir(), 'copilot-reasoning-timing-')); - const path = join(directory, 'session.db'); - const database = store.add(await SessionDatabase.open(path)); - let restored: SessionDatabase | undefined; + for (const boundary of ['markdown', 'tool'] as const) { + test(`restores separate 5s and 12s runs and their ${boundary} boundary after a database restart`, async () => { + const directory = await fs.mkdtemp(join(tmpdir(), 'copilot-reasoning-runs-')); + const path = join(directory, 'session.db'); + const database = store.add(await SessionDatabase.open(path)); + let restored: SessionDatabase | undefined; + try { + const writes: Promise[] = []; + const timing = store.add(new CopilotReasoningTiming( + () => { }, + (turnId, responseId, parts) => writes.push(database.setAssistantResponseParts(turnId, responseId, parts)), + )); + timing.start('host-turn', 'first', undefined); + timing.append('First', undefined); + clock.tick(5000); + if (boundary === 'markdown') { + timing.markdown('host-turn', 'between', 'Between', undefined); + } else { + timing.toolCall('host-turn', 'tool', undefined); + } + clock.tick(20_000); + timing.start('host-turn', 'second', undefined); + timing.append('Second', undefined); + clock.tick(12_000); + timing.markdown('host-turn', 'answer', 'Done', undefined); + timing.completeMessage('assistant-event', 'FirstSecond', boundary === 'markdown' ? 'BetweenDone' : 'Done', undefined); + await Promise.all(writes); + await database.close(); + restored = store.add(await SessionDatabase.open(path)); + const session = URI.parse('ahp-session:/opaque-session'); + const events: ISessionEvent[] = [ + { type: 'user.message', id: 'user', data: { content: 'Request' } }, + { type: 'assistant.message', id: 'assistant-event', data: { content: boundary === 'markdown' ? 'BetweenDone' : 'Done', reasoningText: 'FirstSecond' } }, + ]; + if (boundary === 'tool') { + events.push( + { type: 'tool.execution_start', data: { toolCallId: 'tool', toolName: 'read_file', arguments: { path: '/test/file.ts' } } }, + { type: 'tool.execution_complete', data: { toolCallId: 'tool', success: true, result: { content: 'Tool result' } } }, + ); + } + const result = await mapSessionEvents(session, restored, toSessionEvents(events), URI.parse('ahp-chat:/opaque-chat'), session); + + assert.deepStrictEqual(result.turns[0].responseParts.map(part => part.kind === ResponsePartKind.ToolCall + ? { kind: part.kind, id: part.toolCall.toolCallId } + : part.kind === ResponsePartKind.Reasoning + ? { kind: part.kind, id: part.id, content: part.content, duration: part.duration } + : part.kind === ResponsePartKind.Markdown ? { kind: part.kind, id: part.id, content: part.content } : { kind: part.kind }), [ + { kind: ResponsePartKind.Reasoning, id: 'first', content: 'First', duration: 5000 }, + boundary === 'markdown' ? { kind: ResponsePartKind.Markdown, id: 'between', content: 'Between' } : { kind: ResponsePartKind.ToolCall, id: 'tool' }, + { kind: ResponsePartKind.Reasoning, id: 'second', content: 'Second', duration: 12_000 }, + { kind: ResponsePartKind.Markdown, id: 'answer', content: 'Done' }, + ]); + } finally { + await restored?.close(); + await database.close(); + await fs.rm(directory, { recursive: true, force: true }); + } + }); + } + + test('replay combines fragments of one run across SDK messages without summing their duration', async () => { + const database = store.add(await SessionDatabase.open(':memory:')); try { const writes: Promise[] = []; const timing = store.add(new CopilotReasoningTiming( () => { }, - (turnId, responseId, value) => writes.push(database.setReasoningTiming(turnId, responseId, value)), + (turnId, responseId, parts) => writes.push(database.setAssistantResponseParts(turnId, responseId, parts)), )); - timing.start('host-turn', 'sdk-reasoning', 'live-part', undefined); - timing.append('Thinking', undefined); - elapsed = 45_000; - timing.completeMessage('assistant-timed', 'Thinking', undefined); + timing.start('host-turn', 'run', undefined); + timing.append('First', undefined); + clock.tick(5000); + timing.completeMessage('first-message', 'First', '', undefined); + clock.tick(7000); + timing.append('Second', undefined); + clock.tick(12_000); + timing.markdown('host-turn', 'answer', 'Done', undefined); + timing.completeMessage('second-message', 'Second', 'Done', undefined); await Promise.all(writes); - await database.close(); - restored = store.add(await SessionDatabase.open(path)); - const session = URI.parse('ahp-session:/opaque-session'); - const result = await mapSessionEvents(session, restored, toSessionEvents([ - { type: 'user.message', id: 'user-timed', data: { content: 'First request' } }, - { type: 'assistant.message', id: 'assistant-timed', data: { content: 'Done', reasoningText: 'Thinking' } }, - { type: 'user.message', id: 'user-older', data: { content: 'Older request' } }, - { type: 'assistant.message', id: 'assistant-older', data: { content: 'Done', reasoningText: 'Thinking' } }, - ]), URI.parse('ahp-chat:/opaque-chat'), session); - - assert.deepStrictEqual(result.turns.flatMap(turn => turn.responseParts.flatMap(part => part.kind === ResponsePartKind.Reasoning - ? [{ content: part.content, startedAt: part.startedAt, duration: part.duration }] : [])), [ - { content: 'Thinking', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, - { content: 'Thinking', startedAt: undefined, duration: undefined }, + const session = URI.parse('ahp-session:/session'); + const result = await mapSessionEvents(session, database, toSessionEvents([ + { type: 'user.message', id: 'user', data: { content: 'Request' } }, + { type: 'assistant.message', id: 'first-message', data: { reasoningText: 'First', content: '' } }, + { type: 'assistant.message', id: 'second-message', data: { reasoningText: 'Second', content: 'Done' } }, + ]), URI.parse('ahp-chat:/chat'), session); + + assert.deepStrictEqual(result.turns[0].responseParts, [ + { kind: ResponsePartKind.Reasoning, id: 'run', content: 'FirstSecond', startedAt: '1970-01-01T00:00:01.000Z', duration: 24_000 }, + { kind: ResponsePartKind.Markdown, id: 'answer', content: 'Done' }, ]); } finally { - await restored?.close(); await database.close(); - await fs.rm(directory, { recursive: true, force: true }); } }); }); diff --git a/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts b/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts index a3906b409c7c4..aad8b93fa14ed 100644 --- a/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts +++ b/src/vs/platform/agentHost/test/node/sessionDatabase.test.ts @@ -10,7 +10,7 @@ import { DeferredPromise } from '../../../../base/common/async.js'; import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../base/test/common/utils.js'; import { DisposableStore } from '../../../../base/common/lifecycle.js'; import { SessionDatabase, runMigrations, sessionDatabaseMigrations, type ISessionDatabaseMigration } from '../../node/sessionDatabase.js'; -import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, AH_META_WORKSPACELESS_DB_KEY, FileEditKind, MessageKind } from '../../common/state/sessionState.js'; +import { AH_META_HAS_WORKSPACE_TRANSITIONS_DB_KEY, AH_META_WORKSPACELESS_DB_KEY, FileEditKind, MessageKind, ResponsePartKind, type ReasoningResponsePart } from '../../common/state/sessionState.js'; import { MAX_TERMINAL_OUTPUT_BYTES, MAX_TOOL_RESULT_RESOURCE_BYTES, type IReviewedFileRecord, type ISessionCatalogSyncPendingSnapshot, type IToolResultResource } from '../../common/sessionDataService.js'; import type { Database } from '@vscode/sqlite3'; import { generateUuid } from '../../../../base/common/uuid.js'; @@ -1018,7 +1018,7 @@ suite('SessionDatabase', () => { tables: await db.getAllTables(), records: await db.getPersistedTurns(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['assistant_response_parts', 'catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], records: [{ kind: 'local', turnId: 'local-1', chatUri: 'chat', anchorTurnId: undefined, seq: 1, payload: '{"id":"local-1"}' }], }); }); @@ -1122,39 +1122,51 @@ suite('SessionDatabase', () => { }); }); - suite('reasoning timing', () => { + suite('reasoning response parts', () => { test('reads submitted writes and preserves a recorded zero', async () => { db = disposables.add(await SessionDatabase.open(':memory:')); - const startedAt = '1970-01-01T00:00:01.000Z'; - const write = db.setReasoningTiming('turn-1', 'response-1', { startedAt, duration: 45_000 }); - const first = [...await db.getReasoningTimings()]; + const part: ReasoningResponsePart = { kind: ResponsePartKind.Reasoning, id: 'run', content: 'Reasoning', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }; + const write = db.setAssistantResponseParts('turn-1', 'response-1', [part]); + const first = [...await db.getAssistantResponseParts()]; await write; - await db.setReasoningTiming('turn-1', 'response-1', { startedAt, duration: 0 }); + await db.setAssistantResponseParts('turn-1', 'response-1', [{ ...part, duration: 0 }]); - assert.deepStrictEqual({ first, updated: [...await db.getReasoningTimings()] }, { - first: [['response-1', { startedAt, duration: 45_000 }]], - updated: [['response-1', { startedAt, duration: 0 }]], + assert.deepStrictEqual({ first, updated: [...await db.getAssistantResponseParts()] }, { + first: [['response-1', [part]]], + updated: [['response-1', [{ ...part, duration: 0 }]]], }); }); test('fork remapping preserves timing and pruning removes it', async () => { db = disposables.add(await SessionDatabase.open(':memory:')); - const timing = { startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }; - await db.setReasoningTiming('old-1', 'response-1', timing); - await db.setReasoningTiming('old-2', 'response-2', timing); + const part: ReasoningResponsePart = { kind: ResponsePartKind.Reasoning, id: 'run', content: 'Reasoning', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }; + await db.setAssistantResponseParts('old-1', 'response-1', [part]); + await db.setAssistantResponseParts('old-2', 'response-2', [part]); await db.remapTurnIds(new Map([['old-1', 'new-1']])); - const forked = [...await db.getReasoningTimings()]; + const forked = [...await db.getAssistantResponseParts()]; await db.deleteTurn('new-1'); - assert.deepStrictEqual({ forked, pruned: [...await db.getReasoningTimings()] }, { - forked: [['response-1', timing]], pruned: [], + assert.deepStrictEqual({ forked, pruned: [...await db.getAssistantResponseParts()] }, { + forked: [['response-1', [part]]], pruned: [], }); }); test('rejects invalid reasoning timing', async () => { db = disposables.add(await SessionDatabase.open(':memory:')); - await assert.rejects(db.setReasoningTiming('turn', 'response', { startedAt: 'invalid', duration: 1 }), /Invalid reasoning timing/); - await assert.rejects(db.setReasoningTiming('turn', 'response', { startedAt: '1970-01-01T00:00:01.000Z', duration: -1 }), /Invalid reasoning timing/); + await assert.rejects(db.setAssistantResponseParts('turn', 'response', [{ kind: ResponsePartKind.Reasoning, id: 'run', content: 'Reasoning', startedAt: 'invalid', duration: 1 }]), /Invalid assistant response parts/); + await assert.rejects(db.setAssistantResponseParts('turn', 'response', [{ kind: ResponsePartKind.Reasoning, id: 'run', content: 'Reasoning', duration: -1 }]), /Invalid assistant response parts/); + }); + + test('upgrades the aggregate timing schema without pretending its totals describe individual runs', async () => { + const legacy = await TestableSessionDatabase.open(':memory:', sessionDatabaseMigrations.filter(migration => migration.version <= 17)); + await legacy.createTurn('turn'); + await legacy.setTurnEventId('turn', 'native-turn'); + await legacy.runRaw(`INSERT INTO reasoning_timing VALUES ('response', 'turn', '1970-01-01T00:00:01.000Z', 17000)`); + db = disposables.add(await TestableSessionDatabase.fromDb(await legacy.ejectDb())); + + assert.deepStrictEqual({ parts: [...await db.getAssistantResponseParts()], nativeTurn: await db.getTurnEventId('turn') }, { + parts: [], nativeTurn: 'native-turn', + }); }); }); @@ -2033,7 +2045,7 @@ suite('SessionDatabase', () => { title: await db.getMetadata('customTitle'), snapshot: await db.getCatalogSyncSnapshot(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['assistant_response_parts', 'catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], title: 'After upgrade', snapshot: snapshot(1), }); @@ -2060,7 +2072,7 @@ suite('SessionDatabase', () => { tables: await upgraded.getAllTables(), snapshot: await upgraded.getCatalogSyncSnapshot(), }, { - tables: ['catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], + tables: ['assistant_response_parts', 'catalog_sync_snapshot', 'chat_drafts', 'file_edits', 'local_turns', 'reasoning_timing', 'reviewed_files', 'session_metadata', 'terminal_outputs', 'tool_result_resources', 'turn_delegation', 'turn_usage', 'turn_workspace_transition', 'turns'], snapshot: snapshot(1), }); }); diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts index 5e3b93f9839ea..8f243ecc1e3f1 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts +++ b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts @@ -359,23 +359,17 @@ export function buildPhrasePool(defaults: string[], configurationService: IConfi } function getFinishedThinkingTitle(parts: readonly IChatThinkingPart[]): string { - let duration = 0; - let hasTiming = false; - for (const part of parts) { - if (!extractTextFromPart(part).trim()) { - continue; - } - if (part.reasoningDurationMs === undefined || !Number.isFinite(part.reasoningDurationMs) || part.reasoningDurationMs < 0) { - return localize('chat.thinking.finishedThinking', "Finished thinking"); - } - duration += part.reasoningDurationMs; - hasTiming = true; - } - return hasTiming - ? localize('chat.thinking.thoughtFor', "Thought for {0}", formatElapsedTime(duration)) + const runs = parts.filter(part => extractTextFromPart(part).trim()); + const duration = runs.length === 1 ? runs[0].reasoningDurationMs : undefined; + return duration !== undefined && Number.isFinite(duration) && duration >= 0 + ? getReasoningDurationLabel(duration) : localize('chat.thinking.finishedThinking', "Finished thinking"); } +function getReasoningDurationLabel(duration: number): string { + return localize('chat.thinking.thoughtFor', "Thought for {0}", formatElapsedTime(duration)); +} + export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implements IChatContentPart { private static _codeBlockRendererSync(_languageId: string, text: string, _raw?: string): HTMLElement { @@ -415,6 +409,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem private textContainer!: HTMLElement; private readonly _markdownResult = this._register(new MutableDisposable()); private readonly renderedThinkingHeaders = new Map(); + private readonly renderedThinkingParts = new Map(); private summaryRowItems: HTMLElement[] = []; private summaryRowResults: (IRenderedMarkdown | undefined)[] = []; private summaryRowTexts: string[] = []; @@ -1178,6 +1173,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem } const cleanedContent = content.trim(); if (!cleanedContent) { + this.renderedThinkingParts.delete(this.textContainer); this._markdownResult.clear(); this.clearSummaryRows(); if (this.textContainer) { @@ -1185,6 +1181,14 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem } return; } + if (this.textContainer) { + const rendered = this.renderedThinkingParts.get(this.textContainer); + if (rendered) { + rendered.part = this.content; + } else { + this.renderedThinkingParts.set(this.textContainer, { part: this.content }); + } + } const headers = getThinkingHeaders(cleanedContent); const summaryRows = splitReasoningSummaryRows(cleanedContent, false, headers); @@ -1428,6 +1432,14 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem return this.containsReasoning; } + public hasReasoningTiming(): boolean { + return this.allThinkingParts.some(part => part.reasoningStartedAt !== undefined || part.reasoningDurationMs !== undefined); + } + + public hasActiveReasoningTiming(): boolean { + return this.content.reasoningStartedAt !== undefined && this.content.reasoningDurationMs === undefined; + } + public hasGroupedItems(): boolean { return this.containsGroupedItems; } @@ -1492,6 +1504,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem this.showFinalizedTitle(title); } } + this.updateReasoningDurationLabels(); this.updateToolChainVisibility(); if (this.isVerboseToolChain) { return; @@ -1644,6 +1657,10 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem this.allThinkingParts[index] = content; } } + const rendered = this.renderedThinkingParts.get(this.textContainer); + if (rendered) { + rendered.part = content; + } this.content = content; // Update any pending lazy thinking item with matching ID so that @@ -1976,6 +1993,39 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem : localize('chat.thinking.finished', 'Finished Working'); } + private updateReasoningDurationLabels(): void { + if (!this.renderedThinkingParts.size) { + return; + } + const sources = new Set([...this.renderedThinkingParts.values()].map(({ part }) => this.thinkingPartSources?.get(part) ?? part)); + const shown = new Set(); + for (const [container, rendered] of this.renderedThinkingParts) { + const part = rendered.part; + const source = this.thinkingPartSources?.get(part) ?? part; + const duration = source.reasoningDurationMs; + let label = rendered.label; + if (duration === undefined || !Number.isFinite(duration) || duration < 0 || shown.has(source)) { + label?.remove(); + continue; + } + shown.add(source); + const text = getReasoningDurationLabel(duration); + if (sources.size === 1 && this.currentTitle === text) { + label?.remove(); + continue; + } + if (!label) { + label = rendered.label = $('.chat-thinking-run-duration'); + } + if (label.parentElement !== container) { + container.prepend(label); + } + if (label.textContent !== text) { + label.textContent = text; + } + } + } + private setFallbackTitle(): void { const finalLabel = this.getFallbackTitle(); this.currentTitle = finalLabel; @@ -2000,6 +2050,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem /** Shows a finished section's title, which a conversation section wipes in after its last activity. */ private showFinalizedTitle(title: string): void { + this.updateReasoningDurationLabels(); if (this.isConversation) { this.showConversationTitle({ title, key: conversationFinishedKey, finished: true }, true); } else { @@ -2848,6 +2899,10 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem } hasSameContent(other: IChatRendererContent, _followingContent: IChatRendererContent[], _element: ChatTreeItem): boolean { + if (other.kind === 'thinking' && other.id === this.content.id && this.hasReasoningTiming() + && (extractTextFromPart(other) !== this.currentThinkingValue || (this.fallbackTitle !== undefined && this.getFallbackTitle() !== this.fallbackTitle))) { + return false; + } // Persistent tool chains and reasoning are separate sections, but a conversation section holds both. if (this.context.suppressProgressShimmer && (other.kind === 'working' || (!this.isConversation && this.isToolChain !== (other.kind !== 'thinking')))) { return false; @@ -2875,6 +2930,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem } override dispose(): void { + this.renderedThinkingParts.clear(); this.isActive = false; this.thinkingPartSources = undefined; if (this.workingSpinnerElement) { diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/media/chatThinkingContent.css b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/media/chatThinkingContent.css index 0942f4d041944..47e86d7cbe7c0 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/media/chatThinkingContent.css +++ b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/media/chatThinkingContent.css @@ -173,6 +173,11 @@ } } +.interactive-session .chat-thinking-box .chat-thinking-run-duration { + color: var(--vscode-descriptionForeground); + margin-bottom: var(--vscode-spacing-size40); +} + /* Lay a conversation's reasoning on its tool rows' line grid: the row keeps their body size, so its icon and rails match theirs, and centers its smaller text on that line. */ .interactive-session .interactive-response.chat-persistent-progress .value .chat-thinking-box.chat-thinking-conversation .chat-used-context-list.chat-thinking-collapsible > .chat-thinking-item.markdown-content { diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts b/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts index 633c319df9c74..ff063a693a22e 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts +++ b/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts @@ -655,6 +655,15 @@ export function shouldCreateGroupedThinkingPart(collapsedToolsMode: CollapsedToo return collapsedToolsMode === CollapsedToolsDisplayMode.Always || separatedFromReasoning; } +function isTimedThinkingPart(part: IChatRendererContent | undefined): part is IChatThinkingPart { + return part?.kind === 'thinking' && (part.reasoningStartedAt !== undefined || part.reasoningDurationMs !== undefined); +} + +function isReasoningTimingBoundary(part: IChatRendererContent | undefined): boolean { + return !!part && !isNestedSubagentContent(part) + && (part.kind === 'markdownContent' || part.kind === 'toolInvocation' || part.kind === 'toolInvocationSerialized'); +} + export function shouldShowFileChangesSummaryForSettings(isComplete: boolean, isLocalSession: boolean, showFileChanges: boolean): boolean { return isComplete && isLocalSession && showFileChanges; } @@ -4642,6 +4651,9 @@ export class ChatListItemRenderer extends Disposable implements ITreeRenderer part.kind === 'thinking' && part.id === progress.id); + if (hasTiming && progress.id !== undefined) { + const index = this._responseParts.findLastIndex(part => part.kind === 'thinking' && part.id === progress.id); const part = this._responseParts[index]; - if (part?.kind === 'thinking') { - Object.assign(part, timing); + const crossedBoundary = this._responseParts.slice(index + 1).some(part => !isNestedSubagentResponsePart(part) + && (part.kind === 'markdownContent' || part.kind === 'toolInvocation' || part.kind === 'toolInvocationSerialized')); + if (part?.kind === 'thinking' && (!currText || !crossedBoundary)) { + if (currText) { + const previous = Array.isArray(part.value) ? part.value.join('') : (part.value ?? ''); + this._responseParts[index] = { ...part, ...timing, value: appendMarkdownString(new MarkdownString(previous), new MarkdownString(currText)).value }; + } else { + Object.assign(part, timing); + } this._contentChanged(quiet); return; } } + if (!currText && progress.id === undefined && !hasTiming) { + const lastOutput = this._responseParts.findLast(part => !isNestedSubagentResponsePart(part) + && (part.kind === 'thinking' || part.kind === 'markdownContent' || part.kind === 'toolInvocation' || part.kind === 'toolInvocationSerialized')); + if (lastOutput?.kind === 'thinking' && (lastOutput.reasoningStartedAt !== undefined || lastOutput.reasoningDurationMs !== undefined)) { + return; + } + } // tries to split thinking chunks if it is an array. only while certain models give us array chunks. // Nested subagent parts render inside their parent card and must not split parent reasoning. @@ -1083,7 +1098,6 @@ export class Response extends AbstractResponse implements IDisposable { const lastText = lastResponsePart && lastResponsePart.kind === 'thinking' ? (Array.isArray(lastResponsePart.value) ? lastResponsePart.value.join('') : (lastResponsePart.value || '')) : ''; - const currText = Array.isArray(progress.value) ? progress.value.join('') : (progress.value || ''); const differentId = lastResponsePart?.kind === 'thinking' && progress.id !== undefined && lastResponsePart.id !== undefined && progress.id !== lastResponsePart.id; if (differentId) { this.finalizeReasoningDuration(); diff --git a/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts b/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts index 56382901237dd..1c166ce205244 100644 --- a/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/widget/chatContentParts/chatThinkingContentPart.test.ts @@ -2086,7 +2086,7 @@ suite('ChatThinkingContentPart', () => { }); }); - test('uses recorded reasoning duration in the generic title', async () => { + test('shows individual run durations instead of a grouped total', async () => { const first = createThinkingPart('Consider how to update the progress renderer.', 'first'); first.reasoningStartedAt = 1000; first.reasoningDurationMs = 1200; @@ -2098,10 +2098,16 @@ suite('ChatThinkingContentPart', () => { part.finalizeTitleIfDefault(); await timeout(0); + part.expandContent(); - assert.deepStrictEqual({ title: snapshot(part).title, ariaLabel: snapshot(part).ariaLabel }, { - title: 'Thought for 3s', - ariaLabel: 'Thought for 3s', + assert.deepStrictEqual({ + title: snapshot(part).title, + ariaLabel: snapshot(part).ariaLabel, + runs: Array.from(part.domNode.querySelectorAll('.chat-thinking-run-duration'), label => label.textContent), + }, { + title: 'Finished thinking', + ariaLabel: 'Finished thinking', + runs: ['Thought for 1s', 'Thought for 2s'], }); }); }); @@ -2419,21 +2425,21 @@ suite('ChatThinkingContentPart', () => { }); }); - test('split array reasoning counts each source duration once', () => { + test('split array reasoning does not combine distinct source durations', () => { const cases: Record = { equalDurations: { parts: [ { kind: 'thinking', value: ['First', 'Second'], reasoningDurationMs: 1200 }, { kind: 'thinking', value: ['Third', 'Fourth'], reasoningDurationMs: 1200 }, ], - title: 'Thought for 2s', + title: 'Finished thinking', }, knownSpan: { parts: [ { kind: 'thinking', value: ['First', 'Second'], reasoningStartedAt: 1000, reasoningDurationMs: 1200 }, { kind: 'thinking', value: ['Third', 'Fourth'], reasoningStartedAt: 5000, reasoningDurationMs: 1200 }, ], - title: 'Thought for 2s', + title: 'Finished thinking', }, unknownTiming: { parts: [ diff --git a/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts b/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts index 4ffd9f57e6c5f..d0f1363f4eb34 100644 --- a/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts @@ -10312,6 +10312,69 @@ suite('ChatListRenderer', () => { renderer.renderElement(node, 0, template); }); + for (const progressVerbosity of [ChatProgressVerbosity.Compact, ChatProgressVerbosity.Verbose, ChatProgressVerbosity.Conversation]) { + for (const boundary of ['markdown', 'tool'] as const) { + test(`reasoning run durations survive reload independently (${progressVerbosity}, ${boundary})`, async () => { + const setup = createPersistentProgressRenderer({ chatMode: ChatModeKind.Agent, progressVerbosity }); + setup.configurationService.setUserConfiguration(ChatConfiguration.CollapseCompletedResponses, false); + const diagnostics: string[] = []; + const snapshot = async (current: ReturnType) => { + current.renderer.renderElement(current.node, 0, current.template); + if (current.response.renderData) { + await Event.toPromise(Event.filter(current.renderer.onDidChangeItemHeight, () => !current.response.renderData)); + } + const thinkingParts = [...new Set(current.template.renderedParts)].filter(part => part instanceof ChatThinkingContentPart); + await Promise.all(thinkingParts.map(part => part.getPendingCollapseAnimation())); + for (const part of thinkingParts) { + part.expandContent(); + } + diagnostics.push(JSON.stringify({ + pending: current.renderer.hasPendingProgressContent(current.response), + sections: thinkingParts.map(part => ({ active: part.getIsActive(), activeTiming: part.hasActiveReasoningTiming(), connected: part.domNode.isConnected, text: part.domNode.textContent })), + })); + return { + labels: Array.from(current.template.value.querySelectorAll('.chat-used-context-label .monaco-button, .chat-thinking-run-duration'), label => label.textContent?.trim()) + .filter(label => label?.startsWith('Thought for ')), + runs: current.request.response?.entireResponse.value.flatMap(part => part.kind === 'thinking' && part.value + ? [{ value: part.value, duration: part.reasoningDurationMs }] : []), + }; + }; + setup.model.acceptResponseProgress(setup.request, { kind: 'thinking', id: 'first', value: 'First run', reasoningStartedAt: 1000 }); + setup.renderer.renderElement(setup.node, 0, setup.template); + setup.model.acceptResponseProgress(setup.request, { kind: 'thinking', id: 'first', value: '', reasoningDurationMs: 5000 }); + if (boundary === 'markdown') { + setup.model.acceptResponseProgress(setup.request, { kind: 'markdownContent', content: new MarkdownString('Between') }); + } else { + const tool = new ChatToolInvocation( + { invocationMessage: 'Reading a file', pastTenseMessage: 'Read a file' }, + { id: 'read_file', displayName: 'Read file', modelDescription: 'Read file', source: ToolDataSource.Internal }, + 'tool', undefined, {}, + ); + setup.model.acceptResponseProgress(setup.request, tool); + await tool.didExecuteTool(undefined); + } + setup.model.acceptResponseProgress(setup.request, { kind: 'thinking', id: 'second', value: 'Second run', reasoningStartedAt: 26_000 }); + setup.renderer.renderElement(setup.node, 0, setup.template); + setup.model.acceptResponseProgress(setup.request, { kind: 'thinking', id: 'second', value: '', reasoningDurationMs: 12_000 }); + setup.model.acceptResponseProgress(setup.request, { kind: 'markdownContent', content: new MarkdownString('Done') }); + setup.request.response?.complete(); + const before = await snapshot(setup); + const value: unknown = revive(JSON.parse(JSON.stringify(setup.model.toJSON()))); + assert.ok(isSerializableSessionData(value)); + setup.disposables.dispose(); + + const restored = createPersistentProgressRenderer({ chatMode: ChatModeKind.Agent, progressVerbosity, initialData: { value, serializer: new ChatSessionOperationLog() } }); + restored.configurationService.setUserConfiguration(ChatConfiguration.CollapseCompletedResponses, false); + const expected = { + labels: ['Thought for 5s', 'Thought for 12s'], + runs: [{ value: 'First run', duration: 5000 }, { value: 'Second run', duration: 12_000 }], + }; + assert.deepStrictEqual({ before, after: await snapshot(restored) }, { before: expected, after: expected }, diagnostics.join('\n')); + restored.disposables.dispose(); + }); + } + } + test('conversation progress collapses reasoning and tool calls into one section with its extracted heading', async () => { const clock = sinon.useFakeTimers({ now: 1_000_000, toFake: ['Date'] }); try { @@ -14106,7 +14169,7 @@ suite('ChatListRenderer', () => { }); for (const values of [['First', 'Second'], ['', 'First', 'Second']]) { - test(`restored array reasoning preserves all text with the Finished thinking fallback (${JSON.stringify(values)})`, async () => { + test(`restored array reasoning preserves all text and its single-run duration (${JSON.stringify(values)})`, async () => { const seed = createPersistentProgressRenderer(); seed.model.acceptResponseProgress(seed.request, { kind: 'markdownContent', content: new MarkdownString('Done') }); seed.request.response!.complete(); @@ -14137,11 +14200,11 @@ suite('ChatListRenderer', () => { title: button?.textContent, first: text?.includes('First'), second: text?.includes('Second'), - }, { title: 'Finished thinking', first: true, second: true }); + }, { title: 'Thought for 1s', first: true, second: true }); }); } - test('array reasoning keeps the Finished thinking fallback when timing arrives later', () => runWithFakedTimers({ useFakeTimers: true, startTime: 1000 }, async () => { + test('array reasoning shows its single-run duration when timing arrives later', () => runWithFakedTimers({ useFakeTimers: true, startTime: 1000 }, async () => { const { disposables, model, request, renderer, template, node } = createPersistentProgressRenderer({ persistentProgress: ChatProgressAnimation.Off, thinkingStyle: ThinkingDisplayMode.Collapsed, @@ -14154,7 +14217,7 @@ suite('ChatListRenderer', () => { model.acceptResponseProgress(request, { kind: 'markdownContent', content: new MarkdownString('Done') }); request.response!.complete(); renderer.renderElement(node, 0, template); - assert.strictEqual(template.value.querySelector('.chat-thinking-box > .chat-used-context-label .monaco-button')?.textContent, 'Finished thinking'); + assert.strictEqual(template.value.querySelector('.chat-thinking-box > .chat-used-context-label .monaco-button')?.textContent, 'Thought for 2s'); } finally { disposables.dispose(); } diff --git a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts index 9f5b6c341ca6f..76389642fa78d 100644 --- a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts +++ b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts @@ -1019,6 +1019,24 @@ suite('ChatModel', () => { } }); + test('managed reasoning remains one run across notifications and SDK completion markers', () => { + const response = testDisposables.add(new Response([])); + response.updateContent({ kind: 'thinking', id: 'run', value: 'First', reasoningStartedAt: 1000 }); + response.updateContent({ kind: 'systemNotification', content: new MarkdownString('Background work completed') }); + response.updateContent({ kind: 'thinking', value: '' }); + response.updateContent({ kind: 'thinking', id: 'run', value: 'Second', reasoningStartedAt: 1000 }); + response.updateContent({ kind: 'thinking', id: 'run', value: [''], reasoningDurationMs: 5000 }); + response.updateContent({ kind: 'markdownContent', content: new MarkdownString('Between') }); + response.updateContent({ kind: 'thinking', id: 'next', value: 'Next', reasoningStartedAt: 8000, reasoningDurationMs: 12_000 }); + + assert.deepStrictEqual(response.value, [ + { kind: 'thinking', id: 'run', value: 'FirstSecond', reasoningStartedAt: 1000, reasoningDurationMs: 5000 }, + { kind: 'systemNotification', content: new MarkdownString('Background work completed') }, + { kind: 'markdownContent', content: new MarkdownString('Between') }, + { kind: 'thinking', id: 'next', value: 'Next', reasoningStartedAt: 8000, reasoningDurationMs: 12_000 }, + ]); + }); + test('keeps consecutive reasoning ids and zero durations distinct', () => { const response = testDisposables.add(new Response([])); response.updateContent({ kind: 'thinking', id: 'first', value: 'First', reasoningDurationMs: 45_000 }); From 4709ddbace575e5dff522b9cd06f682690e3daed Mon Sep 17 00:00:00 2001 From: Justin Chen Date: Fri, 30 Oct 2026 10:11:05 -0700 Subject: [PATCH 3/4] chat: fix imported and late reasoning timing Persist imported response projections against synthesized Copilot event IDs before resume. Refresh timing labels on finalized reasoning sections, including array and grouped content, and keep AHP timing provider-owned even when optional timing fields are absent. Add import/reopen, late visible/ARIA label, and untimed reconnect regressions while preserving local-provider measurement. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../node/copilot/buildSessionEvents.ts | 15 ++++- .../agentHost/node/copilot/copilotAgent.ts | 20 ++++++- src/vs/platform/agentHost/test/node/README.md | 4 ++ .../test/node/buildSessionEvents.test.ts | 58 ++++++++++++++++++- .../agentHost/test/node/copilotAgent.test.ts | 19 +++++- .../agentHost/stateToProgressAdapter.ts | 1 + .../chatThinkingContentPart.ts | 27 +++++++++ .../chat/browser/widget/chatListRenderer.ts | 3 + .../chat/common/chatService/chatService.ts | 2 + .../contrib/chat/common/model/chatModel.ts | 12 ++-- .../agentHostChatContribution.test.ts | 49 +++++++++++++++- .../stateToProgressAdapter.test.ts | 14 ++--- .../browser/widget/chatListRenderer.test.ts | 55 ++++++++++++++++++ .../chat/test/common/model/chatModel.test.ts | 33 +++++++++++ 14 files changed, 288 insertions(+), 24 deletions(-) diff --git a/src/vs/platform/agentHost/node/copilot/buildSessionEvents.ts b/src/vs/platform/agentHost/node/copilot/buildSessionEvents.ts index 63a5c801f1082..6e8cd4e6d9242 100644 --- a/src/vs/platform/agentHost/node/copilot/buildSessionEvents.ts +++ b/src/vs/platform/agentHost/node/copilot/buildSessionEvents.ts @@ -6,7 +6,7 @@ import type { JsonValue, SessionEvent } from '@github/copilot-sdk'; import { isObject } from '../../../../base/common/types.js'; import { generateUuid, isUUID } from '../../../../base/common/uuid.js'; -import { getInlineToolInput, ResponsePartKind, ToolCallStatus, ToolResultContentType, TurnState, type ToolCallCompletedState, type ToolResultContent, type ToolResultSubagentContent, type Turn } from '../../common/state/sessionState.js'; +import { getInlineToolInput, ResponsePartKind, ToolCallStatus, ToolResultContentType, TurnState, type MarkdownResponsePart, type ReasoningResponsePart, type ToolCallCompletedState, type ToolResultContent, type ToolResultSubagentContent, type Turn } from '../../common/state/sessionState.js'; /** * Default schema version stamped on the synthesized `session.start` event. @@ -44,6 +44,8 @@ export interface IBuildSessionEventsOptions { readonly schemaVersion?: number; /** Base time for the synthesized (monotonically increasing) event timestamps. Defaults to now. */ readonly startTime?: Date; + /** Associates original response parts with their synthesized user-turn and assistant-event IDs. */ + readonly onAssistantMessage?: (turnId: string, responseId: string, parts: readonly (MarkdownResponsePart | ReasoningResponsePart)[]) => void; } /** @@ -167,8 +169,9 @@ export function buildSessionEventsFromTurns(turns: readonly Turn[], options: IBu // UUID (the runtime rejects non-UUID event ids) so the reconstructed turn // keeps the id the SDK's fork/truncate RPCs address and a caller can seed // a matching protocol turn; otherwise mint a fresh UUID. + const turnId = isUUID(turn.id) ? turn.id : generateUuid(); push({ - id: isUUID(turn.id) ? turn.id : generateUuid(), + id: turnId, parentId, timestamp: nextTimestamp(), type: 'user.message', @@ -180,12 +183,14 @@ export function buildSessionEventsFromTurns(turns: readonly Turn[], options: IBu let markdown = ''; let reasoning = ''; + let parts: (MarkdownResponsePart | ReasoningResponsePart)[] = []; const flushAssistantMessage = (): void => { if (!markdown && !reasoning) { return; } + const responseId = generateUuid(); push({ - id: generateUuid(), + id: responseId, parentId, timestamp: nextTimestamp(), type: 'assistant.message', @@ -196,8 +201,10 @@ export function buildSessionEventsFromTurns(turns: readonly Turn[], options: IBu ...(options.model ? { model: options.model } : {}), }, }); + options.onAssistantMessage?.(turnId, responseId, parts); markdown = ''; reasoning = ''; + parts = []; }; for (const part of turn.responseParts) { @@ -210,11 +217,13 @@ export function buildSessionEventsFromTurns(turns: readonly Turn[], options: IBu flushAssistantMessage(); } markdown += part.content; + parts.push({ ...part }); } else if (part.kind === ResponsePartKind.Reasoning) { if (markdown) { flushAssistantMessage(); } reasoning += part.content; + parts.push({ ...part }); } else if (part.kind === ResponsePartKind.ToolCall && part.toolCall.status === ToolCallStatus.Completed) { // Flush accumulated assistant text before the tool call so the // reconstructed part order matches the original interleaving. diff --git a/src/vs/platform/agentHost/node/copilot/copilotAgent.ts b/src/vs/platform/agentHost/node/copilot/copilotAgent.ts index a017891c2e085..c1af91666a6fb 100644 --- a/src/vs/platform/agentHost/node/copilot/copilotAgent.ts +++ b/src/vs/platform/agentHost/node/copilot/copilotAgent.ts @@ -69,7 +69,7 @@ import { AhpErrorCodes, AHP_SESSION_NOT_FOUND, JsonRpcErrorCodes, ProtocolError import { ICopilotConfigSlashCommandState } from '../../common/copilotConfigSlashCommands.js'; import { ICopilotHomeService } from '../../../environment/common/copilotHome.js'; import { CopilotCustomizationInstallations } from './customizations/copilotCustomizationInstallations.js'; -import { ISessionDataService, SESSION_DB_FILENAME, type ISessionDatabase } from '../../common/sessionDataService.js'; +import { ISessionDataService, SESSION_DB_FILENAME, type ISessionDatabase, type StoredAssistantResponsePart } from '../../common/sessionDataService.js'; import { IAgentHostProxyResolver } from '../agentHostProxyResolver.js'; import { writeUserDataCertificatesFile } from '../../../request/node/certificates.js'; import { MODEL_REFRESH_BASE_DELAY_MS, MODEL_REFRESH_MAX_ATTEMPTS, MODEL_REFRESH_MAX_DELAY_MS, modelRefreshBackoff } from '../shared/modelRefreshRetry.js'; @@ -79,7 +79,7 @@ import { ProtectedResourceMetadata, type AgentCustomization, type AgentSelection import { ActionType, AuthRequiredReason, type AuthRequiredParams, type SessionAction } from '../../common/state/sessionActions.js'; import { areAdditionalWorkingDirectoriesEqual } from '../../common/state/sessionWorkingDirectories.js'; import { getRepositoryRootFromWorktree } from '../../common/worktreePaths.js'; -import { CustomizationLoadStatus, CustomizationType, ChatInputResponseKind, customizationId, buildChatUri, AH_META_WORKSPACELESS_DB_KEY, AH_META_IS_ARCHIVED_DB_KEY, AH_META_IS_DONE_DB_KEY, AH_META_EHCLI_ADOPTED_DB_KEY, AH_META_EHCLI_LAST_TURN_DB_KEY, AH_META_IS_READ_DB_KEY, SessionStatus, withSessionEhcliAdoptable, withSessionStatusFlag, withSessionWorkspaceless, type ChildCustomization, type ClientPluginCustomization, type Customization, type DirectoryCustomization, type ISessionFolderPickerDecision, type MessageAttachment, type PendingMessage, type PluginCustomization, type PolicyState, type ChatInputAnswer, type ToolCallResult, type Turn, type UsageInfo } from '../../common/state/sessionState.js'; +import { CustomizationLoadStatus, CustomizationType, ChatInputResponseKind, customizationId, buildChatUri, AH_META_WORKSPACELESS_DB_KEY, AH_META_IS_ARCHIVED_DB_KEY, AH_META_IS_DONE_DB_KEY, AH_META_EHCLI_ADOPTED_DB_KEY, AH_META_EHCLI_LAST_TURN_DB_KEY, AH_META_IS_READ_DB_KEY, ResponsePartKind, SessionStatus, withSessionEhcliAdoptable, withSessionStatusFlag, withSessionWorkspaceless, type ChildCustomization, type ClientPluginCustomization, type Customization, type DirectoryCustomization, type ISessionFolderPickerDecision, type MessageAttachment, type PendingMessage, type PluginCustomization, type PolicyState, type ChatInputAnswer, type ToolCallResult, type Turn, type UsageInfo } from '../../common/state/sessionState.js'; import { CopilotChatDiscovery, ICopilotChatDiscoveryScan } from './copilotChatDiscovery.js'; import { getByokLmAgentModelId, resolveByokLmEnablement } from '../../common/agentHostByokLm.js'; import { isCustomizationEnabled } from '../../common/customizationEnablement.js'; @@ -6031,13 +6031,29 @@ export class CopilotAgent extends Disposable implements IAgent { // so the git probe and file I/O overlap on the session-creation path. const projectPromise = projectFromCopilotContext({ cwd: workingDirectory.fsPath }, this._gitService); const eventsPath = resourceJoinPath(this._copilotHomeService.home, 'session-state', sessionId, 'events.jsonl').fsPath; + const responses: { turnId: string; responseId: string; parts: readonly StoredAssistantResponsePart[] }[] = []; const jsonl = buildSessionEventLogFromTurns(importConfig.turns, { sessionId, workingDirectory: workingDirectory.fsPath, model: model?.id, + onAssistantMessage: (turnId, responseId, parts) => { + if (parts.some(part => part.kind === ResponsePartKind.Reasoning)) { + responses.push({ turnId, responseId, parts }); + } + }, }); await fs.mkdir(dirname(eventsPath), { recursive: true }); await fs.writeFile(eventsPath, jsonl, 'utf8'); + if (responses.length) { + const reference = this._sessionDataService.openDatabase(this._resolveChatStorageScope(chat)); + try { + for (const response of responses) { + await reference.object.setAssistantResponseParts(response.turnId, response.responseId, response.parts); + } + } finally { + reference.dispose(); + } + } // Persist metadata before resume so `_resumeSession` can resolve the // working directory and model. diff --git a/src/vs/platform/agentHost/test/node/README.md b/src/vs/platform/agentHost/test/node/README.md index 05754d9922006..79e2eb648f508 100644 --- a/src/vs/platform/agentHost/test/node/README.md +++ b/src/vs/platform/agentHost/test/node/README.md @@ -20,8 +20,12 @@ Copilot measures runs with a monotonic clock and stores the observed ordering of Recorded parts follow turn remapping and pruning. The earlier draft's aggregate `reasoning_timing` rows are not reinterpreted as per-run timings. Unknown history and unfinished runs remain untimed rather than counting time while the host is stopped. This does not add capture to other providers or estimate older history. +Conversation import stores the original reasoning projections against the synthesized assistant-message IDs before resuming the SDK session, so imported durations also survive restart. The workbench marks every AHP thinking part as provider-owned independently of whether it carries timing values; a live delta after reconnect must never turn a locally observed tail into a persisted total. Local, non-AHP providers retain their existing client-side timing. + Single-run thinking headers use labels such as "Thought for 5s". Conversation grouping remains available, but its expanded reasoning rows show their individual durations instead of a group-wide sum. `copilotReasoningTiming.test.ts` covers 5s/12s markdown/tool boundaries through a real database restart and a single run spanning SDK messages. The provider, model, database, and renderer tests cover live boundaries, identity, migration, serialization, grouped display, and accessible text. +Finalized sections refresh both visible and accessible timing when a duration arrives after answer text. Regression coverage includes string/array reasoning, an earlier run inside a completed conversation group, and an import/event-log/database reopen round trip. + ## Mission Control session configuration The Mission Control listener publishes Copilot Host's `approvalMode` vocabulary (`manual`, `assisted`, `allow-all`) in place of VS Code's native `autoApprove` vocabulary (`default`, `assisted`, `autoApprove`). The independent `mode` property advertises `interactive`, `plan`, and `autopilot`. Local clients and persisted configuration keep the native representation; Mission Control requests, snapshots, action echoes, and reconnect replay use the wire representation. diff --git a/src/vs/platform/agentHost/test/node/buildSessionEvents.test.ts b/src/vs/platform/agentHost/test/node/buildSessionEvents.test.ts index e6648f0d10013..c429a801a533b 100644 --- a/src/vs/platform/agentHost/test/node/buildSessionEvents.test.ts +++ b/src/vs/platform/agentHost/test/node/buildSessionEvents.test.ts @@ -4,6 +4,9 @@ *--------------------------------------------------------------------------------------------*/ import assert from 'assert'; +import { promises as fs } from 'fs'; +import { tmpdir } from 'os'; +import { join } from '../../../../base/common/path.js'; import { ensureNoDisposablesAreLeakedInTestSuite } from '../../../../base/test/common/utils.js'; import { URI } from '../../../../base/common/uri.js'; import { generateUuid, isUUID } from '../../../../base/common/uuid.js'; @@ -12,15 +15,17 @@ import { MessageKind, ResponsePartKind, ToolCallConfirmationReason, ToolCallStat import { buildSessionEventLogFromTurns, buildSessionEventsFromTurns, serializeSessionEventsToJsonl } from '../../node/copilot/buildSessionEvents.js'; import { mapSessionEvents as mapSessionEventsWithRouting } from '../../node/copilot/mapSessionEvents.js'; import type { SessionEvent } from '@github/copilot-sdk'; +import type { ISessionDatabase } from '../../common/sessionDataService.js'; +import { SessionDatabase } from '../../node/sessionDatabase.js'; suite('buildSessionEventsFromTurns — reverse of mapSessionEvents', () => { - ensureNoDisposablesAreLeakedInTestSuite(); + const store = ensureNoDisposablesAreLeakedInTestSuite(); const session = AgentSession.uri('copilot', 'test-session'); const sessionId = 'test-session'; - function mapSessionEvents(session: URI, db: undefined, events: Parameters[2]) { + function mapSessionEvents(session: URI, db: ISessionDatabase | undefined, events: Parameters[2]) { return mapSessionEventsWithRouting(session, db, events, URI.parse(buildChatUri(session, 'default')), session); } @@ -134,6 +139,55 @@ suite('buildSessionEventsFromTurns — reverse of mapSessionEvents', () => { assert.deepStrictEqual(project(reconstructed), project(turns)); }); + for (const sourceId of [generateUuid(), 'local-turn']) { + test(`imported reasoning timing survives event-log and database reopen (${isUUID(sourceId) ? 'UUID' : 'local'} turn id)`, async () => { + const directory = await fs.mkdtemp(join(tmpdir(), 'import-reasoning-timing-')); + const databasePath = join(directory, 'session.db'); + const database = store.add(await SessionDatabase.open(databasePath)); + let reopened: SessionDatabase | undefined; + try { + const timed = { kind: ResponsePartKind.Reasoning as const, id: 'timed-run', content: 'Consider the answer', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }; + const zero = { kind: ResponsePartKind.Reasoning as const, id: 'zero-run', content: 'Check the result', duration: 0 }; + const untimed = { kind: ResponsePartKind.Reasoning as const, id: 'untimed-run', content: 'Older reasoning' }; + const writes: Promise[] = []; + const events = buildSessionEventsFromTurns([userTurn(sourceId, 'Question', [ + timed, toolCallPart('read', 'read_file', '{"path":"file.ts"}', 'Result'), + zero, markdown('Answer'), untimed, markdown('Done'), + ])], { + sessionId, + onAssistantMessage: (turnId, responseId, parts) => { + if (parts.some(part => part.kind === ResponsePartKind.Reasoning)) { + writes.push(database.setAssistantResponseParts(turnId, responseId, parts)); + } + }, + }); + await fs.writeFile(join(directory, 'events.jsonl'), serializeSessionEventsToJsonl(events)); + await Promise.all(writes); + await database.close(); + reopened = store.add(await SessionDatabase.open(databasePath)); + const savedEvents: SessionEvent[] = (await fs.readFile(join(directory, 'events.jsonl'), 'utf8')).trim().split('\n').map(line => JSON.parse(line)); + const { turns } = await mapSessionEvents(session, reopened, savedEvents); + const restoredReasoning = turns[0].responseParts.filter(part => part.kind === ResponsePartKind.Reasoning); + const importedTurnId = savedEvents.find(event => event.type === 'user.message')!.id; + await reopened.deleteTurn(importedTurnId); + + assert.deepStrictEqual({ + restoredReasoning, + turnId: turns[0].id, + remainingParts: [...await reopened.getAssistantResponseParts()], + }, { + restoredReasoning: [timed, zero, untimed], + turnId: importedTurnId, + remainingParts: [], + }); + } finally { + await reopened?.close(); + await database.close(); + await fs.rm(directory, { recursive: true, force: true }); + } + }); + } + test('emits an abort for a cancelled turn so it reconstructs as cancelled with its text', async () => { const id = generateUuid(); const turns: Turn[] = [{ diff --git a/src/vs/platform/agentHost/test/node/copilotAgent.test.ts b/src/vs/platform/agentHost/test/node/copilotAgent.test.ts index b4c3c20e2af57..b54f1caa5d896 100644 --- a/src/vs/platform/agentHost/test/node/copilotAgent.test.ts +++ b/src/vs/platform/agentHost/test/node/copilotAgent.test.ts @@ -78,7 +78,7 @@ import { AgentSession, GITHUB_COPILOT_PROTECTED_RESOURCE, type AgentSignal, type import { AgentHostClientType } from '../../common/agentHostClientInfo.js'; import { subagentChatUri } from '../../common/agentHostChatMinting.js'; import { AgentHostClientConnectionKind, AgentHostLaunchKind, AgentHostTransportKind, createUnknownAgentHostClientTelemetryContext } from '../../common/agentHostTelemetry.js'; -import { ISessionDataService } from '../../common/sessionDataService.js'; +import { ISessionDataService, type StoredAssistantResponsePart } from '../../common/sessionDataService.js'; import { buildNonPtyShellTerminalUri } from '../../common/nonPtyShellTerminalUri.js'; import { buildDefaultChatUri, buildChatUri, buildSubagentChatUri, buildSubagentSessionUri, CustomizationLoadStatus, MessageKind, readSessionEhcliAdoptable, readSessionWorkspaceless, ResponsePartKind, ToolResultContentType, TurnState, customizationId, AH_META_EHCLI_ADOPTED_DB_KEY, AH_META_EHCLI_LAST_TURN_DB_KEY, AH_META_IS_ARCHIVED_DB_KEY, AH_META_IS_READ_DB_KEY, AH_META_WORKSPACELESS_DB_KEY, type ClientPluginCustomization, type Customization, type PluginCustomization, type ToolCallResult, type Turn, RuleCustomization } from '../../common/state/sessionState.js'; import { ChatOriginKind, CustomizationEnablementKind, CustomizationType, McpServerStatus, SessionStatus, ToolCallContributorKind, type AgentSelection, type ModelSelection, type ProtectedResourceMetadata, type ToolDefinition } from '../../common/state/protocol/state.js'; @@ -22473,7 +22473,10 @@ suite('CopilotAgent', () => { id: 'imported-turn-1', state: TurnState.Complete, message: { text: 'Remember IMPORT_ALPHA.', origin: { kind: MessageKind.User } }, - responseParts: [{ kind: ResponsePartKind.Markdown, id: 'response', content: 'ready' }], + responseParts: [ + { kind: ResponsePartKind.Reasoning, id: 'imported-reasoning', content: 'Considering the request', startedAt: '1970-01-01T00:00:01.000Z', duration: 45_000 }, + { kind: ResponsePartKind.Markdown, id: 'response', content: 'ready' }, + ], usage: {}, }; @@ -22482,6 +22485,16 @@ suite('CopilotAgent', () => { workingDirectories: [workingDirectory], importConversation: { turns: [turn] }, }); + const events: SessionEvent[] = (await fs.readFile(join(getCopilotHomePath(userHome.fsPath, {}), 'session-state', 'import-exact-chat', 'events.jsonl'), 'utf8')).trim().split('\n').map(line => JSON.parse(line)); + const database = sessionDataService.openDatabase(session); + let importedReasoning: readonly StoredAssistantResponsePart[] | undefined; + try { + const parts = await database.object.getAssistantResponseParts(); + const reasoningEvent = events.find(event => event.type === 'assistant.message' && event.data.reasoningText); + importedReasoning = reasoningEvent && parts.get(reasoningEvent.id); + } finally { + database.dispose(); + } // The imported session's default chat is bound directly by // `createChat` itself (via `_importConversation` → @@ -22492,11 +22505,13 @@ suite('CopilotAgent', () => { resultSession: result.session.toString(), boundSdkId: chatBackings(agent).get(chat.toString())?.sdkSessionId, live: hasLiveChat(agent, chat), + importedReasoning, }, { resumeCalls: ['import-exact-chat'], resultSession: session.toString(), boundSdkId: 'import-exact-chat', live: true, + importedReasoning: [turn.responseParts[0]], }); await agent.chats.sendMessage(chat, 'follow-up', [workingDirectory], undefined, 'turn-2', undefined, exactChatContext(result.session, chat, result.session)); diff --git a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts index f477e7dc8ad1e..5548d443abad7 100644 --- a/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts +++ b/src/vs/workbench/contrib/chat/browser/agentSessions/agentHost/stateToProgressAdapter.ts @@ -1699,6 +1699,7 @@ export function reasoningPartToThinking(part: ReasoningResponsePart, value = par kind: 'thinking', id: part.id, value, + reasoningTimingSource: 'provider', ...(startedAt !== undefined && Number.isFinite(startedAt) ? { reasoningStartedAt: startedAt } : {}), ...(typeof part.duration === 'number' && Number.isFinite(part.duration) && part.duration >= 0 ? { reasoningDurationMs: part.duration } : {}), }; diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts index 8f243ecc1e3f1..1769f6299fe05 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts +++ b/src/vs/workbench/contrib/chat/browser/widget/chatContentParts/chatThinkingContentPart.ts @@ -410,6 +410,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem private readonly _markdownResult = this._register(new MutableDisposable()); private readonly renderedThinkingHeaders = new Map(); private readonly renderedThinkingParts = new Map(); + private readonly reasoningDurationSnapshots = new Map(); private summaryRowItems: HTMLElement[] = []; private summaryRowResults: (IRenderedMarkdown | undefined)[] = []; private summaryRowTexts: string[] = []; @@ -1635,6 +1636,31 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem this.setExpanded(true); } + public updateReasoningTiming(content: IChatThinkingPart): void { + const duration = content.reasoningDurationMs; + const key = content.id ?? content; + if (duration === undefined || Object.is(this.reasoningDurationSnapshots.get(key), duration)) { + return; + } + let matched = false; + for (const part of this.allThinkingParts) { + const source = this.thinkingPartSources?.get(part) ?? part; + if (source !== content && (content.id === undefined || source.id !== content.id)) { + continue; + } + matched = true; + part.reasoningDurationMs = source.reasoningDurationMs = duration; + if (content.reasoningStartedAt !== undefined) { + part.reasoningStartedAt = source.reasoningStartedAt = content.reasoningStartedAt; + } + } + if (matched) { + this.reasoningDurationSnapshots.set(key, duration); + this.updateDropdownClickability(); + this._onDidChangeHeight.fire(); + } + } + public updateThinking(content: IChatThinkingPart): void { // If disposed, ignore late updates coming from renderer diffing if (this._store.isDisposed) { @@ -2930,6 +2956,7 @@ export class ChatThinkingContentPart extends ChatThinkingStyleContentPart implem } override dispose(): void { + this.reasoningDurationSnapshots.clear(); this.renderedThinkingParts.clear(); this.isActive = false; this.thinkingPartSources = undefined; diff --git a/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts b/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts index ff063a693a22e..32340e94ae135 100644 --- a/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts +++ b/src/vs/workbench/contrib/chat/browser/widget/chatListRenderer.ts @@ -4461,6 +4461,9 @@ export class ChatListItemRenderer extends Disposable implements ITreeRenderer part.kind === 'thinking' && part.id === progress.id); const part = this._responseParts[index]; const crossedBoundary = this._responseParts.slice(index + 1).some(part => !isNestedSubagentResponsePart(part) @@ -1081,10 +1083,10 @@ export class Response extends AbstractResponse implements IDisposable { return; } } - if (!currText && progress.id === undefined && !hasTiming) { + if (!currText && progress.id === undefined && !hasTiming && !hasProviderTiming) { const lastOutput = this._responseParts.findLast(part => !isNestedSubagentResponsePart(part) && (part.kind === 'thinking' || part.kind === 'markdownContent' || part.kind === 'toolInvocation' || part.kind === 'toolInvocationSerialized')); - if (lastOutput?.kind === 'thinking' && (lastOutput.reasoningStartedAt !== undefined || lastOutput.reasoningDurationMs !== undefined)) { + if (lastOutput?.kind === 'thinking' && (lastOutput.reasoningTimingSource === 'provider' || lastOutput.reasoningStartedAt !== undefined || lastOutput.reasoningDurationMs !== undefined)) { return; } } @@ -1105,7 +1107,7 @@ export class Response extends AbstractResponse implements IDisposable { const isEmpty = (s: string) => s.length === 0; if (isEmpty(currText)) { this.finalizeReasoningDuration(); - } else if (!this._activeReasoning && !restored && !hasTiming) { + } else if (!this._activeReasoning && !restored && !hasTiming && !hasProviderTiming && !(lastResponsePart?.kind === 'thinking' && !differentId && lastResponsePart.reasoningTimingSource === 'provider')) { // Replayed history keeps its recorded timing; this clock only measures live reasoning. this._activeReasoning = { part: progress, startedAt: Date.now() }; } diff --git a/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts b/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts index ae4d90eef02bd..6255585f93a68 100644 --- a/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/agentSessions/agentHostChatContribution.test.ts @@ -169,7 +169,7 @@ import { ChatQuestionCarouselData } from '../../../common/model/chatProgressType import { ChatPlanReviewData } from '../../../common/model/chatProgressTypes/chatPlanReviewData.js'; import { ChatElicitationRequestPart } from '../../../common/model/chatProgressTypes/chatElicitationRequestPart.js'; import { ChatToolInvocation } from '../../../common/model/chatProgressTypes/chatToolInvocation.js'; -import { ChatModel, ChatResponseModel, IntendedModelSlot, reviveSerializableInputState, type ChatRequestModel, type IChatModel, type IChatModelInputState, type IChatPendingRequest, type IChatRequestModel, type IChatResponseModel, type IInputModel } from '../../../common/model/chatModel.js'; +import { ChatModel, ChatResponseModel, IntendedModelSlot, Response, reviveSerializableInputState, type ChatRequestModel, type IChatModel, type IChatModelInputState, type IChatPendingRequest, type IChatRequestModel, type IChatResponseModel, type IInputModel } from '../../../common/model/chatModel.js'; import { ModelSelectionReason } from '../../../common/modelSelection.js'; import { convertBufferToScreenshotVariable } from '../../../browser/attachments/chatScreenshotContext.js'; import { AgentHostCompletionReferenceKind, ChatPasteAttachmentMetadata, createChatReferenceVariableEntry, isChatReferenceVariableEntry, toAgentHostCompletionVariableEntry, type IChatRequestVariableEntry } from '../../../common/attachments/chatVariableEntries.js'; @@ -18474,13 +18474,56 @@ suite('AgentHostChatContribution', () => { complete: session.isCompleteObs?.get(), }, { parts: [ - { kind: 'thinking', id: 'reasoning', value: 'Already received', reasoningStartedAt: 1000 }, - { kind: 'thinking', id: 'reasoning', value: '', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'reasoning', value: 'Already received', reasoningTimingSource: 'provider', reasoningStartedAt: 1000 }, + { kind: 'thinking', id: 'reasoning', value: '', reasoningTimingSource: 'provider', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, ], complete: true, }); }); + test('untimed reasoning remains producer-owned through reconnect and continued live output', async () => { + const { sessionHandler, agentHostService } = createContribution(disposables, { backendSessionScheme: 'unused-allocation-scheme' }); + const backend = URI.parse('ahp-session:/untimed-reconnect'); + const chat = 'ahp-chat:/opaque-untimed-chat'; + const state = makeSessionStateWithActiveTurn(backend.toString()); + agentHostService.seedSessionMetadata(backend, 'copilot'); + agentHostService.sessionStates.set(backend.toString(), { + ...state, + defaultChat: chat, + chats: [{ resource: chat, title: state.title, status: SessionStatus.InProgress, modifiedAt: '2025-01-01T00:00:00.000Z', origin: { kind: ChatOriginKind.User } }], + activeTurn: { ...state.activeTurn!, responseParts: [{ kind: ResponsePartKind.Reasoning, id: 'reasoning', content: 'Restored prefix' }] }, + }); + const session = await sessionHandler.provideChatSessionContent(URI.parse('agent-host-copilot:/untimed-reconnect'), CancellationToken.None); + disposables.add(session); + const response = disposables.add(new Response([])); + let consumed = 0; + const consume = (restored: boolean) => { + const parts = session.progressObs?.get() ?? []; + for (const part of parts.slice(consumed)) { + if (part.kind === 'thinking' || part.kind === 'markdownContent') { + response.updateContent(part, false, restored); + } + } + consumed = parts.length; + }; + consume(true); + const clock = sinon.useFakeTimers({ now: 900_000, toFake: ['Date'] }); + try { + agentHostService.fireAction({ channel: chat, action: { type: ActionType.ChatReasoning, turnId: 'turn-active', partId: 'reasoning', content: ' continued' }, serverSeq: 100, origin: undefined }); + consume(false); + clock.tick(5000); + agentHostService.fireAction({ channel: chat, action: { type: ActionType.ChatResponsePart, turnId: 'turn-active', part: { kind: ResponsePartKind.Markdown, id: 'answer', content: 'Answer' } }, serverSeq: 101, origin: undefined }); + consume(false); + response.finalizeReasoningDuration(); + + assert.deepStrictEqual(JSON.parse(JSON.stringify(response.value.filter(part => part.kind === 'thinking'))), [ + { kind: 'thinking', id: 'reasoning', value: 'Restored prefix continued', reasoningTimingSource: 'provider' }, + ]); + } finally { + clock.restore(); + } + }); + test('includes reasoning in initial progress', async () => { const { sessionHandler, agentHostService } = createContribution(disposables); diff --git a/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts b/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts index 3a5d02824bf15..7cb0212e9bb23 100644 --- a/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/agentSessions/stateToProgressAdapter.test.ts @@ -1074,10 +1074,10 @@ suite('stateToProgressAdapter', () => { })], 'participant'); assert.deepStrictEqual(history[1].type === 'response' ? history[1].parts : undefined, [ - { kind: 'thinking', id: 'timed', value: 'Measured', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, - { kind: 'thinking', id: 'zero', value: 'Immediate', reasoningDurationMs: 0 }, - { kind: 'thinking', id: 'unknown', value: 'Older host' }, - { kind: 'thinking', id: 'invalid', value: 'Invalid metadata' }, + { kind: 'thinking', id: 'timed', value: 'Measured', reasoningTimingSource: 'provider', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'zero', value: 'Immediate', reasoningTimingSource: 'provider', reasoningDurationMs: 0 }, + { kind: 'thinking', id: 'unknown', value: 'Older host', reasoningTimingSource: 'provider' }, + { kind: 'thinking', id: 'invalid', value: 'Invalid metadata', reasoningTimingSource: 'provider' }, ]); }); @@ -4312,7 +4312,7 @@ suite('stateToProgressAdapter', () => { ]), undefined); assert.deepStrictEqual(result, [ - { kind: 'thinking', id: 'reasoning', value: 'Assessing final output steps' }, + { kind: 'thinking', id: 'reasoning', value: 'Assessing final output steps', reasoningTimingSource: 'provider' }, { kind: 'thinking', value: '' }, ]); }); @@ -4570,8 +4570,8 @@ suite('stateToProgressAdapter', () => { ]), 'remote-host'); assert.deepStrictEqual(result, [ - { kind: 'thinking', id: 'completed', value: 'Already thought', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, - { kind: 'thinking', id: 'active', value: 'Still thinking', reasoningStartedAt: 60_000 }, + { kind: 'thinking', id: 'completed', value: 'Already thought', reasoningTimingSource: 'provider', reasoningStartedAt: 1000, reasoningDurationMs: 45_000 }, + { kind: 'thinking', id: 'active', value: 'Still thinking', reasoningTimingSource: 'provider', reasoningStartedAt: 60_000 }, ]); }); diff --git a/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts b/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts index d0f1363f4eb34..8cee23b13e968 100644 --- a/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts +++ b/src/vs/workbench/contrib/chat/test/browser/widget/chatListRenderer.test.ts @@ -10312,6 +10312,61 @@ suite('ChatListRenderer', () => { renderer.renderElement(node, 0, template); }); + for (const value of ['Reasoning without a heading', ['First reasoning piece', 'Second reasoning piece']]) { + test(`late reasoning timing refreshes a finalized header and ARIA label (${typeof value})`, async () => { + const { model, request, renderer, template, node } = createPersistentProgressRenderer({ progressVerbosity: ChatProgressVerbosity.Compact }); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'late-timing', value }, false, true); + model.acceptResponseProgress(request, { kind: 'markdownContent', content: new MarkdownString('The answer') }); + renderer.renderElement(node, 0, template); + await Promise.all(template.renderedParts?.flatMap(part => part instanceof ChatThinkingContentPart ? [part.getPendingCollapseAnimation()] : []) ?? []); + const section = template.value.querySelector('.chat-thinking-box'); + const button = section?.querySelector('.chat-used-context-label .monaco-button'); + const before = { title: button?.textContent, ariaLabel: button?.ariaLabel }; + + model.acceptResponseProgress(request, { kind: 'thinking', id: 'late-timing', value: '', reasoningDurationMs: 45_000 }); + renderer.renderElement(node, 0, template); + const after = { title: button?.textContent, ariaLabel: button?.ariaLabel }; + request.response?.complete(); + + assert.deepStrictEqual({ + before, + after, + preservesSection: template.value.querySelector('.chat-thinking-box') === section, + }, { + before: { title: 'Finished thinking', ariaLabel: 'Finished thinking' }, + after: { title: 'Thought for 45s', ariaLabel: 'Thought for 45s' }, + preservesSection: true, + }); + }); + } + + test('late reasoning timing refreshes an earlier run inside a finalized conversation group', async () => { + const { model, request, renderer, template, node } = createPersistentProgressRenderer({ progressVerbosity: ChatProgressVerbosity.Conversation }); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'first', value: 'First run', reasoningTimingSource: 'provider' }, false, true); + const tool = new ChatToolInvocation( + { invocationMessage: 'Reading', pastTenseMessage: 'Read' }, + { id: 'read_file', displayName: 'Read file', modelDescription: 'Read file', source: ToolDataSource.Internal }, + 'between', undefined, {}, + ); + model.acceptResponseProgress(request, tool); + await tool.didExecuteTool(undefined); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'second', value: 'Second run', reasoningTimingSource: 'provider', reasoningDurationMs: 12_000 }); + model.acceptResponseProgress(request, { kind: 'markdownContent', content: new MarkdownString('The answer') }); + renderer.renderElement(node, 0, template); + const section = template.renderedParts?.find(part => part instanceof ChatThinkingContentPart); + assert.ok(section instanceof ChatThinkingContentPart); + section.expandContent(); + const labels = () => Array.from(section.domNode.querySelectorAll('.chat-thinking-run-duration'), element => element.textContent); + const before = labels(); + + model.acceptResponseProgress(request, { kind: 'thinking', id: 'first', value: '', reasoningTimingSource: 'provider', reasoningDurationMs: 5000 }); + renderer.renderElement(node, 0, template); + const after = labels(); + request.response?.complete(); + + assert.deepStrictEqual({ before, after }, { before: ['Thought for 12s'], after: ['Thought for 5s', 'Thought for 12s'] }); + }); + for (const progressVerbosity of [ChatProgressVerbosity.Compact, ChatProgressVerbosity.Verbose, ChatProgressVerbosity.Conversation]) { for (const boundary of ['markdown', 'tool'] as const) { test(`reasoning run durations survive reload independently (${progressVerbosity}, ${boundary})`, async () => { diff --git a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts index 76389642fa78d..c0e4606cb4903 100644 --- a/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts +++ b/src/vs/workbench/contrib/chat/test/common/model/chatModel.test.ts @@ -995,6 +995,39 @@ suite('ChatModel', () => { } }); + test('provider-owned reasoning stays untimed after reconnect while local providers retain measurement', () => { + const clock = sinon.useFakeTimers({ now: 900_000 }); + try { + const model = testDisposables.add(instantiationService.createInstance(ChatModel, undefined, { initialLocation: ChatAgentLocation.Chat, canUseTools: true })); + const request = model.addRequest({ text: 'Question', parts: [] }, { variables: [] }, 0); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'remote', value: 'Restored', reasoningTimingSource: 'provider' }, false, true); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'remote', value: ' continuation', reasoningTimingSource: 'provider' }); + clock.tick(5000); + model.acceptResponseProgress(request, { kind: 'markdownContent', content: new MarkdownString('Remote answer') }); + model.acceptResponseProgress(request, { kind: 'thinking', id: 'local', value: 'Local reasoning' }); + clock.tick(2000); + request.response?.complete(); + const restored = testDisposables.add(instantiationService.createInstance(ChatModel, { value: model.toJSON(), serializer: undefined! }, { initialLocation: ChatAgentLocation.Chat, canUseTools: true })); + + assert.deepStrictEqual(restored.getRequests()[0].response?.entireResponse.value.filter(part => part.kind === 'thinking'), [ + { kind: 'thinking', id: 'remote', value: 'Restored continuation', reasoningTimingSource: 'provider' }, + { kind: 'thinking', id: 'local', value: 'Local reasoning', reasoningStartedAt: 905_000, reasoningDurationMs: 2000 }, + ]); + } finally { + clock.restore(); + } + }); + + test('provider-owned timing accepts a late recorded zero without a client-clock fallback', () => { + const response = testDisposables.add(new Response([])); + response.updateContent({ kind: 'thinking', id: 'remote', value: 'Reasoning', reasoningTimingSource: 'provider' }); + response.updateContent({ kind: 'markdownContent', content: new MarkdownString('Answer') }); + response.updateContent({ kind: 'thinking', id: 'remote', value: '', reasoningTimingSource: 'provider', reasoningDurationMs: 0 }); + response.finalizeReasoningDuration(); + + assert.deepStrictEqual(response.value[0], { kind: 'thinking', id: 'remote', value: 'Reasoning', reasoningTimingSource: 'provider', reasoningDurationMs: 0 }); + }); + test('applies timing-only reasoning updates without replaying text or measuring a remote clock', () => { const clock = sinon.useFakeTimers({ now: 900_000 }); try { From e7137e35ae475694d4254ff5e3247537ff46d65e Mon Sep 17 00:00:00 2001 From: Justin Chen Date: Fri, 30 Oct 2026 10:33:46 -0700 Subject: [PATCH 4/4] agentHost: pin merged reasoning timing protocol Reference the merge commit of microsoft/agent-host-protocol#552. The generated protocol sources are unchanged. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- src/vs/platform/agentHost/common/state/protocol/.ahp-version | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/vs/platform/agentHost/common/state/protocol/.ahp-version b/src/vs/platform/agentHost/common/state/protocol/.ahp-version index e081b9c944eb9..79a97aca599a0 100644 --- a/src/vs/platform/agentHost/common/state/protocol/.ahp-version +++ b/src/vs/platform/agentHost/common/state/protocol/.ahp-version @@ -1 +1 @@ -f0cf2adc +d7a5579b