diff --git a/packages/agent-core-v2/docs/di-scope-domains.puml b/packages/agent-core-v2/docs/di-scope-domains.puml index d582cdaf2..b334cc869 100644 --- a/packages/agent-core-v2/docs/di-scope-domains.puml +++ b/packages/agent-core-v2/docs/di-scope-domains.puml @@ -197,6 +197,7 @@ llmRequester --> contextProjector #34495E llmRequester --> toolRegistry #34495E llmRequester --> profile #34495E llmRequester --> log #34495E +llmRequester --> telemetry #34495E llmRequester --> usage #34495E llmRequester --> modelProvider #34495E llmRequester --> config #34495E @@ -211,6 +212,8 @@ permissionGate --> permissionRules #34495E permissionGate --> permissionPolicy #34495E permissionGate --> telemetry #34495E permissionGate --> toolExecutor #34495E +permissionPolicy --> plan #34495E +permissionPolicy --> swarm #34495E permissionMode --> wireRecord #34495E permissionMode --> record #34495E permissionMode --> record #34495E diff --git a/packages/agent-core-v2/scripts/check-domain-layers.mjs b/packages/agent-core-v2/scripts/check-domain-layers.mjs index 6b0747c1c..6661fa251 100644 --- a/packages/agent-core-v2/scripts/check-domain-layers.mjs +++ b/packages/agent-core-v2/scripts/check-domain-layers.mjs @@ -235,6 +235,10 @@ function domainFromRel(rel, { exemptRootFile }) { * - `permissionGate>approval` : permissionGate(Agent) requests approval(Session broker). * - `userTool>interaction` : userTool(Agent) requests host-side execution * through the Session interaction broker. + * - `permissionPolicy>plan` : plan-mode approval policies need the current + * Agent plan state to approve/deny tool use. + * - `permissionPolicy>swarm` : swarm-mode approval policy needs the current + * Agent swarm state to approve AgentSwarm. * - `skill>turn` : skill activate starts a turn (same Agent scope intent). * - `turn>agentLifecycle` : turn cancels sub-agents via lifecycle handle. * - `swarm>agentLifecycle`: swarm spawns/manages sub-agents. @@ -260,6 +264,8 @@ const ALLOWED_EXCEPTIONS = new Set([ '_base>hostEnvironment', 'permissionGate>approval', 'userTool>interaction', + 'permissionPolicy>plan', + 'permissionPolicy>swarm', 'skill>turn', 'turn>agentLifecycle', 'swarm>agentLifecycle', diff --git a/packages/agent-core-v2/src/agent/fullCompaction/fullCompactionService.ts b/packages/agent-core-v2/src/agent/fullCompaction/fullCompactionService.ts index 6ffa46498..4e8164c6b 100644 --- a/packages/agent-core-v2/src/agent/fullCompaction/fullCompactionService.ts +++ b/packages/agent-core-v2/src/agent/fullCompaction/fullCompactionService.ts @@ -396,6 +396,7 @@ export class AgentFullCompactionService extends Disposable implements IAgentFull { messages, maxOutputSize: compactionMaxOutputSize, + requestLogFields: { requestKind: 'full_compaction' }, }, undefined, signal, diff --git a/packages/agent-core-v2/src/agent/llmRequester/llmRequester.ts b/packages/agent-core-v2/src/agent/llmRequester/llmRequester.ts index 86f939175..9dd8f0920 100644 --- a/packages/agent-core-v2/src/agent/llmRequester/llmRequester.ts +++ b/packages/agent-core-v2/src/agent/llmRequester/llmRequester.ts @@ -7,11 +7,9 @@ import type { TokenUsage, Tool, } from '#/app/llmProtocol'; +import type { LogContext } from '#/app/log'; -export interface LLMRequestLogFields { - readonly turnStep: string; - readonly attempt?: string; -} +export type LLMRequestLogFields = Readonly; export interface LLMRequestRetryContext { readonly failedAttempt: number; diff --git a/packages/agent-core-v2/src/agent/llmRequester/llmRequesterService.ts b/packages/agent-core-v2/src/agent/llmRequester/llmRequesterService.ts index 0d9157106..6f15ffa9e 100644 --- a/packages/agent-core-v2/src/agent/llmRequester/llmRequesterService.ts +++ b/packages/agent-core-v2/src/agent/llmRequester/llmRequesterService.ts @@ -7,9 +7,10 @@ * completion-token budget, then drives `model.request(input, signal)` with * bounded retry. Forwards streamed `part` events to the caller's `onPart` * handler, records `usage` through `IAgentUsageService`, resolves to an - * `LLMRequestFinish` on the `finish` event, and logs the outbound request - * (config deduplicated by content, plus per-request fields) through `log`. - * Bound at Agent scope. + * `LLMRequestFinish` on the `finish` event, logs the request lifecycle + * (config deduplicated by content, request/response/failure lines, plus + * per-request fields) through `log`, and reports provider failures through + * `telemetry`. Bound at Agent scope. */ import { createHash } from 'node:crypto'; @@ -23,16 +24,24 @@ import { IAgentToolRegistryService } from '#/agent/toolRegistry'; import { IAgentUsageService } from '#/agent/usage'; import { IConfigService } from '#/app/config'; import { + APIConnectionError, + APIContextOverflowError, + APIEmptyResponseError, + APIStatusError, + APITimeoutError, emptyUsage, + isContextOverflowStatusError, isRetryableGenerateError, type Message, type ThinkingEffort, + type TokenUsage, type Tool, } from '#/app/llmProtocol'; -import { ILogService } from '#/app/log'; +import { ILogService, type LogContext } from '#/app/log'; import type { KimiModelOverrides, Model, ModelRequestEvent } from '#/app/model'; import { applyCompletionBudget, resolveCompletionBudget } from '#/app/model/completionBudget'; import type { Protocol } from '#/app/protocol'; +import { ITelemetryService } from '#/app/telemetry'; import type { LLMRequestFinish, @@ -92,6 +101,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { @IAgentUsageService private readonly usage: IAgentUsageService, @IConfigService private readonly config: IConfigService, @ILogService private readonly log: ILogService, + @ITelemetryService private readonly telemetry: ITelemetryService, ) {} async request( @@ -108,6 +118,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { onPart: LLMRequestPartHandler, signal: AbortSignal | undefined, ): Promise { + const startedAt = Date.now(); const maxAttempts = Math.max(overrides.retry?.maxAttempts ?? DEFAULT_MAX_RETRY_ATTEMPTS, 1); if (maxAttempts <= 1) { @@ -115,6 +126,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { return await this.executeRequestAttempt(overrides, onPart, signal, 1, maxAttempts); } catch (error) { this.logRequestFailure(error, overrides, signal, 1, maxAttempts); + this.trackApiError(error, startedAt, signal); throw error; } } @@ -126,6 +138,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { } catch (error) { if (attempt >= maxAttempts || !isRetryableGenerateError(error)) { this.logRequestFailure(error, overrides, signal, attempt, maxAttempts); + this.trackApiError(error, startedAt, signal); throw error; } @@ -165,24 +178,32 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { maxAttempts: number, ): void { if (isAbortError(error) || signal?.aborted === true) return; - const payload: { - turnStep?: string; - attempt: string; - model: string; - errorName: string; - errorMessage: string; - statusCode?: number; - } = { + const payload: LogContext = { + ...overrides.requestLogFields, attempt: `${String(attempt)}/${String(maxAttempts)}`, model: this.profile.data().modelAlias ?? 'unknown', ...retryErrorFields(error), }; - if (overrides.requestLogFields?.turnStep !== undefined) { - payload.turnStep = overrides.requestLogFields.turnStep; - } this.log.warn('llm request failed', payload); } + private trackApiError( + error: unknown, + startedAt: number, + signal: AbortSignal | undefined, + ): void { + if (isAbortError(error) || signal?.aborted === true) return; + const properties: Record = { + error_type: apiErrorType(error), + model: this.profile.data().modelAlias ?? 'unknown', + retryable: isRetryableGenerateError(error), + duration_ms: Math.max(0, Date.now() - startedAt), + }; + const statusCode = apiStatusCode(error); + if (statusCode !== undefined) properties['status_code'] = statusCode; + this.telemetry.track('api_error', properties); + } + private async runRequest( request: ResolvedLLMRequest, onPart: LLMRequestPartHandler, @@ -237,6 +258,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { const usageModel = request.modelAlias; this.usage.record(usageModel, usage, request.usageContext); this.contextSize.measured(request.messages, [message], usage); + this.logResponse(request.requestLogFields, usage, timing); return { message, @@ -277,7 +299,7 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { } private logRequest(input: LLMRequestLogInput): void { - const requestLogFields = input.fields ?? {}; + const requestLogFields: LLMRequestLogFields = input.fields ?? {}; const config = { provider: input.protocol, model: input.modelName, @@ -297,15 +319,32 @@ export class AgentLLMRequesterService implements IAgentLLMRequesterService { } const partialMessageCount = input.messages.filter((message) => message.partial === true).length; - const requestFields: { - turnStep?: string; - attempt?: string; - partialMessageCount?: number; - } = { ...requestLogFields }; - if (partialMessageCount > 0) requestFields.partialMessageCount = partialMessageCount; + const requestFields: LogContext = { ...requestLogFields }; + if (partialMessageCount > 0) requestFields['partialMessageCount'] = partialMessageCount; this.log.info('llm request', requestFields); } + private logResponse( + fields: LLMRequestLogFields | undefined, + usage: TokenUsage, + timing: LLMStreamTiming | undefined, + ): void { + if (timing === undefined) return; + const payload: LogContext = { + ...fields, + ttftMs: timing.firstTokenLatencyMs, + streamDurationMs: timing.streamDurationMs, + outputTokens: usage.output, + }; + if (timing.requestBuildMs !== undefined) payload['requestBuildMs'] = timing.requestBuildMs; + if (timing.serverFirstTokenMs !== undefined) { + payload['serverFirstTokenMs'] = timing.serverFirstTokenMs; + } + if (timing.serverDecodeMs !== undefined) payload['serverDecodeMs'] = timing.serverDecodeMs; + if (timing.clientConsumeMs !== undefined) payload['clientConsumeMs'] = timing.clientConsumeMs; + this.log.info('llm response', payload); + } + private defaultTools(): readonly Tool[] { return this.tools .list() @@ -323,7 +362,7 @@ function requestOverridesForAttempt( attempt: number, maxAttempts: number, ): LLMRequestOverrides { - if (attempt === 1 || overrides.requestLogFields === undefined) { + if (attempt === 1) { return overrides; } return { @@ -343,6 +382,30 @@ function fingerprint(content: string): string { return createHash('sha256').update(content).digest('hex'); } +function apiErrorType(error: unknown): string { + if (error instanceof APIContextOverflowError) return 'context_overflow'; + if (error instanceof APIStatusError) { + if (isContextOverflowStatusError(error.statusCode, error.message)) return 'context_overflow'; + if (error.statusCode === 429) return 'rate_limit'; + if (error.statusCode === 401 || error.statusCode === 403) return 'auth'; + if (error.statusCode >= 500) return '5xx_server'; + if (error.statusCode >= 400) return '4xx_client'; + } + if (error instanceof APIConnectionError) return 'network'; + if (error instanceof APITimeoutError) return 'timeout'; + if (error instanceof APIEmptyResponseError) return 'empty_response'; + return 'other'; +} + +function apiStatusCode(error: unknown): number | undefined { + if (error instanceof APIStatusError) return error.statusCode; + if (typeof error !== 'object' || error === null) return undefined; + const statusCode = (error as Record)['statusCode']; + if (typeof statusCode === 'number') return statusCode; + const status = (error as Record)['status']; + return typeof status === 'number' ? status : undefined; +} + registerScopedService( LifecycleScope.Agent, IAgentLLMRequesterService, diff --git a/packages/agent-core-v2/src/agent/loop/errors.ts b/packages/agent-core-v2/src/agent/loop/errors.ts index fd43ad0de..73d682ced 100644 --- a/packages/agent-core-v2/src/agent/loop/errors.ts +++ b/packages/agent-core-v2/src/agent/loop/errors.ts @@ -3,6 +3,7 @@ */ import { KimiError, registerErrorDomain, type ErrorDomain } from '#/_base/errors'; +import type { LoopInterruptReason } from './types'; export const LoopErrors = { codes: { @@ -42,6 +43,33 @@ export function isMaxStepsExceededError(error: unknown): boolean { return error instanceof KimiError && error.code === LoopErrors.codes.LOOP_MAX_STEPS_EXCEEDED; } +export class LoopTurnInterruptedError extends Error { + override readonly cause: unknown; + readonly steps: number; + readonly activeStep?: number; + readonly reason: LoopInterruptReason; + + constructor( + cause: unknown, + options: { + readonly steps: number; + readonly activeStep?: number; + readonly reason: LoopInterruptReason; + }, + ) { + super(errorMessage(cause), { cause }); + this.name = 'LoopTurnInterruptedError'; + this.cause = cause; + this.steps = options.steps; + this.activeStep = options.activeStep; + this.reason = options.reason; + } +} + +export function isLoopTurnInterruptedError(error: unknown): error is LoopTurnInterruptedError { + return error instanceof LoopTurnInterruptedError; +} + export function isAbortError(err: unknown): boolean { if (err instanceof Error) { return err.name === 'AbortError'; diff --git a/packages/agent-core-v2/src/agent/loop/loopService.ts b/packages/agent-core-v2/src/agent/loop/loopService.ts index abbdbf347..b9f04a0b9 100644 --- a/packages/agent-core-v2/src/agent/loop/loopService.ts +++ b/packages/agent-core-v2/src/agent/loop/loopService.ts @@ -28,6 +28,7 @@ import { createMaxStepsExceededError, errorMessage, isAbortError, + LoopTurnInterruptedError, isMaxStepsExceededError, } from './errors'; import { IAgentLoopService, type TurnWillStopContext } from './loop'; @@ -123,10 +124,18 @@ export class AgentLoopService implements IAgentLoopService { if (isContextOverflowError(error)) { const context = { turnId, signal, error, handled: false }; - await this.hooks.onContextOverflow.run(context); + try { + await this.hooks.onContextOverflow.run(context); + } catch (hookError) { + throw new LoopTurnInterruptedError(hookError, { + steps, + activeStep, + reason: 'error', + }); + } if (context.handled) continue; } - throw error; + throw new LoopTurnInterruptedError(error, { steps, activeStep, reason }); } return { stopReason, steps }; @@ -218,18 +227,6 @@ export class AgentLoopService implements IAgentLoopService { signal.throwIfAborted(); this.emitStepCompleted(turnId, currentStep, stepUuid, usage, finishReason, response); - if (response.timing !== undefined) { - this.log.info('llm response', { - turnStep, - ttftMs: response.timing.firstTokenLatencyMs, - requestBuildMs: response.timing.requestBuildMs, - serverFirstTokenMs: response.timing.serverFirstTokenMs, - streamDurationMs: response.timing.streamDurationMs, - serverDecodeMs: response.timing.serverDecodeMs, - clientConsumeMs: response.timing.clientConsumeMs, - outputTokens: response.usage.output, - }); - } const afterStepContext = { turnId, signal, usage, continueTurn: false }; try { diff --git a/packages/agent-core-v2/src/agent/toolExecutor/toolExecutorService.ts b/packages/agent-core-v2/src/agent/toolExecutor/toolExecutorService.ts index 48c821646..d895e3358 100644 --- a/packages/agent-core-v2/src/agent/toolExecutor/toolExecutorService.ts +++ b/packages/agent-core-v2/src/agent/toolExecutor/toolExecutorService.ts @@ -44,6 +44,11 @@ export interface ToolExecutionTask { readonly execute: (signal: AbortSignal) => Promise; } +interface TimedToolResult { + readonly result: ToolResult; + readonly durationMs: number; +} + export class AgentToolExecutorService implements IAgentToolExecutorService { declare readonly _serviceBrand: undefined; readonly hooks = { @@ -88,7 +93,7 @@ export class AgentToolExecutorService implements IAgentToolExecutorService { } } - const rawResults = await this.executeBatch( + const timedResults = await this.executeBatch( preparedTasks.map(({ task }) => task), options.signal, ); @@ -96,12 +101,13 @@ export class AgentToolExecutorService implements IAgentToolExecutorService { const results: ToolResult[] = []; for (let index = 0; index < preparedTasks.length; index += 1) { const { call } = preparedTasks[index]!; - const rawResult = rawResults[index]!; + const timedResult = timedResults[index]!; + const rawResult = timedResult.result; const finalized = await this.finalizeToolResult(call, rawResult, options); results.push(finalized); await dispatchToolResult(call, finalized, options); - this.trackToolCall(call, finalized); + this.trackToolCall(call, finalized, timedResult.durationMs); } return results; @@ -110,14 +116,16 @@ export class AgentToolExecutorService implements IAgentToolExecutorService { private trackToolCall( call: PreflightedToolCall, result: ToolResult, + durationMs: number, ): void { - const properties: Record = { + const outcome = toolTelemetryOutcome(result); + const properties: Record = { tool_name: call.toolName, - outcome: toolTelemetryOutcome(result), - duration_ms: 'TODO', - dup_type: 'TODO', + outcome, + duration_ms: durationMs, + dup_type: 'normal', }; - if (result.isError === true) properties['error_type'] = 'TODO'; + if (result.isError === true) properties['error_type'] = toolTelemetryErrorType(outcome); this.telemetry.track('tool_call', properties); } @@ -224,12 +232,20 @@ export class AgentToolExecutorService implements IAgentToolExecutorService { private async executeBatch( tasks: ToolExecutionTask[], signal: AbortSignal, - ): Promise { - const scheduler = new ToolScheduler(); + ): Promise { + const scheduler = new ToolScheduler(); const pendingResults = tasks.map((task) => scheduler.add({ accesses: task.accesses, - start: async () => ({ result: task.execute(signal) }), + start: async () => { + const startedAt = Date.now(); + return { + result: task.execute(signal).then((result) => ({ + result, + durationMs: Math.max(0, Date.now() - startedAt), + })), + }; + }, }), ); @@ -593,6 +609,11 @@ function toolTelemetryOutcome(result: ToolResult): 'success' | 'error' | 'cancel : 'error'; } +function toolTelemetryErrorType(outcome: 'success' | 'error' | 'cancelled'): string { + if (outcome === 'cancelled') return 'cancelled'; + return 'error'; +} + function toolOutputText(output: ToolResult['output']): string { if (typeof output === 'string') return output; return output diff --git a/packages/agent-core-v2/src/agent/turn/turn.ts b/packages/agent-core-v2/src/agent/turn/turn.ts index 9caa1597a..456efb940 100644 --- a/packages/agent-core-v2/src/agent/turn/turn.ts +++ b/packages/agent-core-v2/src/agent/turn/turn.ts @@ -6,6 +6,7 @@ import type { Hooks } from '#/hooks'; export interface TurnResult { readonly reason: TurnEndReason; readonly error?: unknown; + readonly steps?: number; } export interface Turn { diff --git a/packages/agent-core-v2/src/agent/turn/turnService.ts b/packages/agent-core-v2/src/agent/turn/turnService.ts index 0724de804..db1d7cd8f 100644 --- a/packages/agent-core-v2/src/agent/turn/turnService.ts +++ b/packages/agent-core-v2/src/agent/turn/turnService.ts @@ -5,6 +5,7 @@ import type { ContextMessage, PromptOrigin } from '#/agent/contextMemory'; import { IAgentContextMemoryService, USER_PROMPT_ORIGIN } from '#/agent/contextMemory'; import { OrderedHookSlot } from '#/hooks'; import { IAgentLoopService, type TurnResult as LoopTurnResult } from '#/agent/loop'; +import { isLoopTurnInterruptedError } from '#/agent/loop/errors'; import { IAgentTelemetryContextService, ITelemetryService } from '#/app/telemetry'; import { IAgentRecordService } from '#/agent/record'; import type { @@ -32,7 +33,6 @@ export class AgentTurnService implements IAgentTurnService { private lastEndedReasonValue: TurnResult['reason'] | undefined; private readonly readyControllers = new WeakMap>(); private readonly readySettled = new WeakSet(); - private readonly interruptedTelemetryTurnIds = new Set(); private readonly turnTelemetry = new Map(); readonly hooks = { @@ -63,13 +63,6 @@ export class AgentTurnService implements IAgentTurnService { } }, ); - this.record.on((event) => { - if (event.type === 'turn.step.interrupted') { - if (typeof event.turnId === 'number' && typeof event.step === 'number') { - this.trackTurnInterrupted(event.turnId, event.step); - } - } - }); } launch(origin: PromptOrigin, promptMessageId?: string): Turn { @@ -127,19 +120,20 @@ export class AgentTurnService implements IAgentTurnService { result = promptHookResult; return result; } - result = toAgentTurnResult( - await this.loop.runTurn(turn.id, turn.abortController.signal), - turn.abortController.signal, - ); + const loopResult = await this.loop.runTurn(turn.id, turn.abortController.signal); + result = toAgentTurnResult(loopResult, turn.abortController.signal); return result; } catch (error) { + const loopInterruptedError = isLoopTurnInterruptedError(error) ? error : undefined; + const resultError = loopInterruptedError?.cause ?? error; + const steps = loopInterruptedError?.steps; if (turn.abortController.signal.aborted) { - result = { reason: 'cancelled', error: turn.abortController.signal.reason }; + result = { reason: 'cancelled', error: turn.abortController.signal.reason, steps }; this.rejectReady(turn, turn.abortController.signal.reason); return result; } - this.rejectReady(turn, error); - result = { reason: 'failed', error }; + this.rejectReady(turn, resultError); + result = { reason: 'failed', error: resultError, steps }; return result; } finally { if (result !== undefined) { @@ -156,13 +150,12 @@ export class AgentTurnService implements IAgentTurnService { this.record.signal({ type: 'error', ...ended.error }); } if (ended.reason !== 'completed') { - this.trackTurnInterrupted(turn.id, 0); + this.trackTurnInterrupted(turn.id, result.steps ?? 0); } } if (result !== undefined) { await this.hooks.onEnded.run({ turn, result }); } - this.interruptedTelemetryTurnIds.delete(turn.id); this.turnTelemetry.delete(turn.id); } } @@ -236,8 +229,6 @@ export class AgentTurnService implements IAgentTurnService { } private trackTurnInterrupted(turnId: number, atStep: number): void { - if (this.interruptedTelemetryTurnIds.has(turnId)) return; - this.interruptedTelemetryTurnIds.add(turnId); const telemetry = this.turnTelemetry.get(turnId) ?? this.telemetry.withContext(this.telemetryContext.get()); telemetry.track('turn_interrupted', { at_step: atStep }); @@ -274,11 +265,12 @@ function toTurnEndedEvent( function toAgentTurnResult(result: LoopTurnResult, signal: AbortSignal): TurnResult { if (result.stopReason === 'aborted') { - return { reason: 'cancelled', error: signal.reason }; + return { reason: 'cancelled', error: signal.reason, steps: result.steps }; } if (result.stopReason === 'filtered') { return { reason: 'failed', + steps: result.steps, error: new KimiError( ErrorCodes.PROVIDER_FILTERED, 'Provider safety policy blocked the response.', @@ -289,7 +281,7 @@ function toAgentTurnResult(result: LoopTurnResult, signal: AbortSignal): TurnRes ), }; } - return { reason: 'completed' }; + return { reason: 'completed', steps: result.steps }; } const LLM_NOT_SET_MESSAGE = 'LLM not set, send "/login" to login'; diff --git a/packages/agent-core-v2/test/llmRequester/kosong-llm.test.ts b/packages/agent-core-v2/test/llmRequester/kosong-llm.test.ts index 8054fd119..221510ca0 100644 --- a/packages/agent-core-v2/test/llmRequester/kosong-llm.test.ts +++ b/packages/agent-core-v2/test/llmRequester/kosong-llm.test.ts @@ -17,6 +17,28 @@ import { type TestAgentContext, } from '../harness'; +interface CapturedLogEntry { + readonly level: 'error' | 'warn' | 'info' | 'debug'; + readonly message: string; + readonly payload: LogPayload | undefined; +} + +function captureLogs(): { logger: Logger; entries: CapturedLogEntry[] } { + const entries: CapturedLogEntry[] = []; + const capture = + (level: CapturedLogEntry['level']) => (message: string, payload?: LogPayload) => { + entries.push({ level, message, payload }); + }; + const logger: Logger = { + error: capture('error'), + warn: capture('warn'), + info: capture('info'), + debug: capture('debug'), + child: () => logger, + }; + return { logger, entries }; +} + describe('LLMRequester service migration coverage', () => { describe('tool-call deltas', () => { let ctx: TestAgentContext; @@ -113,9 +135,11 @@ describe('LLMRequester service migration coverage', () => { throw new APIConnectionError('terminated'); } return { + id: 'retry-response', message: { role: 'assistant', content: [], toolCalls: [] }, usage: emptyUsage(), finishReason: 'completed', + rawFinishReason: 'stop', }; }), ); @@ -185,13 +209,14 @@ describe('LLMRequester service migration coverage', () => { await expect( llmRequester.request({ - requestLogFields: { turnStep: '0.1' }, + requestLogFields: { requestKind: 'direct_test', turnStep: '0.1' }, retry: { maxAttempts: 1 }, }), ).rejects.toMatchObject({ message: 'temporary provider failure' }); expect(entries).toEqual([ expect.objectContaining({ + requestKind: 'direct_test', turnStep: '0.1', attempt: '1/1', model: expect.any(String), @@ -209,9 +234,12 @@ describe('LLMRequester service migration coverage', () => { let llmRequester: IAgentLLMRequesterService; let profile: IAgentProfileService; let requestMaxTokens: unknown; + let logEntries: CapturedLogEntry[]; beforeEach(() => { requestMaxTokens = undefined; + const { logger, entries } = captureLogs(); + logEntries = entries; ctx = createTestAgent( llmGenerateServices(async (provider, _systemPrompt, _tools, _messages, callbacks, options) => { requestMaxTokens = ( @@ -251,6 +279,7 @@ describe('LLMRequester service migration coverage', () => { }, }, })), + logServices(logger), ); llmRequester = ctx.get(IAgentLLMRequesterService); profile = ctx.get(IAgentProfileService); @@ -291,6 +320,30 @@ describe('LLMRequester service migration coverage', () => { ); }); + it('logs successful LLM responses with caller-provided request fields', async () => { + await collectLLMRequest((onPart) => + llmRequester.request( + { requestLogFields: { requestKind: 'direct_test', turnStep: '0.1' } }, + onPart, + ), + ); + + const responseLogs = logEntries.filter((entry) => entry.message === 'llm response'); + expect(responseLogs).toHaveLength(1); + const payload = responseLogs[0]?.payload as Record; + expect(payload).toMatchObject({ + requestKind: 'direct_test', + turnStep: '0.1', + ttftMs: expect.any(Number), + streamDurationMs: expect.any(Number), + outputTokens: expect.any(Number), + serverDecodeMs: expect.any(Number), + clientConsumeMs: expect.any(Number), + }); + expect(payload).not.toHaveProperty('requestBuildMs'); + expect(payload).not.toHaveProperty('serverFirstTokenMs'); + }); + it('applies a per-request output budget override', async () => { await llmRequester.request({ maxOutputSize: 123_000 }); diff --git a/packages/agent-core-v2/test/toolExecutor/tool-executor.test.ts b/packages/agent-core-v2/test/toolExecutor/tool-executor.test.ts index 4e79d29c3..2d11bcb83 100644 --- a/packages/agent-core-v2/test/toolExecutor/tool-executor.test.ts +++ b/packages/agent-core-v2/test/toolExecutor/tool-executor.test.ts @@ -72,8 +72,8 @@ describe('AgentToolExecutorService', () => { properties: expect.objectContaining({ tool_name: 'echo', outcome: 'success', - duration_ms: 'TODO', - dup_type: 'TODO', + duration_ms: expect.any(Number), + dup_type: 'normal', }), }); }); @@ -91,6 +91,16 @@ describe('AgentToolExecutorService', () => { calls: ['call_missing'], results: ['call_missing'], }); + expect(telemetryEvents).toContainEqual({ + event: 'tool_call', + properties: expect.objectContaining({ + tool_name: 'missing', + outcome: 'error', + duration_ms: expect.any(Number), + dup_type: 'normal', + error_type: 'error', + }), + }); }); it('records an error tool.result when args fail tool parameter validation', async () => {