basant307/AI_Governance_Project
045
1/**2 * @license3 * Copyright 2026 Qwen Team4 * SPDX-License-Identifier: Apache-2.05 */6 7import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';8import { ROOT_CONTEXT, SpanStatusCode } from '@opentelemetry/api';9 10const mockState = vi.hoisted(() => ({11 sdkInitialized: true,12 // Toggles to force span.setAttributes/setStatus to throw — exercises the13 // try/catch hardening in end*Span helpers (span.end() must still run).14 throwOnSetAttributes: false,15 throwOnSetStatus: false,16 // When set, `context.active()` returns a context that carries this fake17 // span and `trace.getSpan()` reports it. Lets tests exercise the18 // active-OTel-span fallback in resolveParentContext (#4212).19 activeOtelSpan: undefined as unknown,20}));21 22const mockMetrics = vi.hoisted(() => ({23 recordApiRequestBreakdown: vi.fn(),24}));25 26vi.mock('./sdk.js', () => ({27 isTelemetrySdkInitialized: () => mockState.sdkInitialized,28}));29 30vi.mock('./metrics.js', () => ({31 recordApiRequestBreakdown: mockMetrics.recordApiRequestBreakdown,32 ApiRequestPhase: {33 REQUEST_PREPARATION: 'request_preparation',34 NETWORK_LATENCY: 'network_latency',35 RESPONSE_PROCESSING: 'response_processing',36 TOKEN_PROCESSING: 'token_processing',37 },38}));39 40interface MockSpanRecord {41 name: string;42 kind: number;43 attributes: Record<string, unknown>;44 setAttributesCalls: Array<Record<string, unknown>>;45 statuses: Array<{ code: number; message?: string }>;46 ended: boolean;47 parentContext?: unknown;48 /** True iff `startSpan` was called with `{ root: true }` (linked-root path). */49 root?: boolean;50 /** Span links captured from the `startSpan` opts. */51 links?: Array<{52 context: { spanId: string; traceId: string };53 attributes?: Record<string, unknown>;54 }>;55}56 57const mockSpans: MockSpanRecord[] = [];58 59vi.mock('@opentelemetry/api', async () => {60 const actual =61 await vi.importActual<typeof import('@opentelemetry/api')>(62 '@opentelemetry/api',63 );64 65 function createMockSpan(66 name: string,67 opts?: {68 kind?: number;69 attributes?: Record<string, unknown>;70 root?: boolean;71 links?: Array<{72 context: { spanId: string; traceId: string };73 attributes?: Record<string, unknown>;74 }>;75 },76 parentCtx?: unknown,77 ): MockSpanRecord & {78 spanContext: () => { spanId: string; traceId: string; traceFlags: number };79 setAttributes: (attrs: Record<string, unknown>) => void;80 setStatus: (status: { code: number; message?: string }) => void;81 end: () => void;82 } {83 const record: MockSpanRecord = {84 name,85 kind: opts?.kind ?? 0,86 attributes: { ...(opts?.attributes ?? {}) },87 setAttributesCalls: [],88 statuses: [],89 ended: false,90 parentContext: parentCtx,91 root: opts?.root,92 links: opts?.links,93 };94 mockSpans.push(record);95 const spanId = Math.random().toString(16).slice(2, 18).padEnd(16, '0');96 return Object.assign(record, {97 spanContext: () => ({98 spanId,99 traceId: '0'.repeat(32),100 traceFlags: 0,101 }),102 setAttributes: (attrs: Record<string, unknown>) => {103 if (mockState.throwOnSetAttributes) {104 throw new Error('setAttributes failed');105 }106 record.setAttributesCalls.push(attrs);107 Object.assign(record.attributes, attrs);108 },109 setStatus: (status: { code: number; message?: string }) => {110 if (mockState.throwOnSetStatus) {111 throw new Error('setStatus failed');112 }113 record.statuses.push(status);114 },115 end: () => {116 record.ended = true;117 },118 });119 }120 121 const mockTracer = {122 startSpan: (123 name: string,124 opts?: { kind?: number; attributes?: Record<string, unknown> },125 parentCtx?: unknown,126 ) => createMockSpan(name, opts, parentCtx),127 };128 129 return {130 ...actual,131 SpanKind: actual.SpanKind,132 SpanStatusCode: actual.SpanStatusCode,133 trace: {134 getTracer: () => mockTracer,135 setSpan: (ctx: unknown, _span: unknown) => ({136 ...(ctx as object),137 __parentSpan: _span,138 }),139 getSpan: (ctx: unknown) =>140 typeof ctx === 'object' && ctx !== null && '__activeSpan' in ctx141 ? (ctx as { __activeSpan: unknown }).__activeSpan142 : undefined,143 wrapSpanContext: actual.trace.wrapSpanContext,144 },145 context: {146 active: () =>147 mockState.activeOtelSpan148 ? { __activeSpan: mockState.activeOtelSpan }149 : {},150 with: <T>(_ctx: unknown, fn: () => T): T => fn(),151 },152 };153});154 155import type { Config } from '../config/config.js';156import {157 startInteractionSpan,158 endInteractionSpan,159 withInteractionSpan,160 startLLMRequestSpan,161 endLLMRequestSpan,162 startToolSpan,163 endToolSpan,164 runInToolSpanContext,165 startToolExecutionSpan,166 endToolExecutionSpan,167 startToolBlockedOnUserSpan,168 endToolBlockedOnUserSpan,169 startHookSpan,170 endHookSpan,171 startSubagentSpan,172 endSubagentSpan,173 runInSubagentSpanContext,174 getActiveInteractionSpan,175 clearSessionTracingForTesting,176 runTTLSweepForTesting,177 truncateSpanError,178} from './session-tracing.js';179import { setSessionContext } from './session-context.js';180 181function createMockConfig(182 overrides: Partial<{183 sessionId: string;184 approvalMode: string;185 }> = {},186): Config {187 return {188 getSessionId: () => overrides.sessionId ?? 'test-session-id',189 getApprovalMode: () => overrides.approvalMode ?? 'suggest',190 } as unknown as Config;191}192 193describe('session-tracing', () => {194 beforeEach(() => {195 clearSessionTracingForTesting();196 mockSpans.length = 0;197 mockState.sdkInitialized = true;198 mockState.throwOnSetAttributes = false;199 mockState.throwOnSetStatus = false;200 mockState.activeOtelSpan = undefined;201 });202 203 afterEach(() => {204 vi.restoreAllMocks();205 });206 207 describe('interaction spans', () => {208 it('starts and ends an interaction span with ok status', () => {209 const config = createMockConfig();210 startInteractionSpan(config, {211 promptId: 'prompt-1',212 model: 'test-model',213 messageType: 'userQuery',214 });215 216 expect(mockSpans).toHaveLength(1);217 expect(mockSpans[0]!.name).toBe('qwen-code.interaction');218 expect(mockSpans[0]!.attributes['session.id']).toBe('test-session-id');219 expect(mockSpans[0]!.attributes['qwen-code.prompt_id']).toBe('prompt-1');220 expect(mockSpans[0]!.attributes['qwen-code.model']).toBe('test-model');221 222 endInteractionSpan('ok');223 224 expect(mockSpans[0]!.ended).toBe(true);225 expect(mockSpans[0]!.statuses).toHaveLength(1);226 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.OK);227 });228 229 it('defaults to ROOT_CONTEXT when no parentContext is provided', async () => {230 await withInteractionSpan(231 createMockConfig({ sessionId: 's' }),232 { promptId: 'p', model: 'm', messageType: 'cron' },233 async () => {},234 );235 236 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');237 expect(span?.parentContext).toBe(ROOT_CONTEXT);238 });239 240 it('runs scoped interaction spans without mutating the global interaction context', async () => {241 const config = createMockConfig({ sessionId: 'scoped-session' });242 const result = await withInteractionSpan(243 config,244 {245 promptId: 'prompt-scoped',246 model: 'test-model',247 messageType: 'acp_prompt',248 parentContext: { parent: 'daemon' } as never,249 },250 async () => 'done',251 );252 253 expect(result).toBe('done');254 expect(mockSpans).toHaveLength(1);255 expect(mockSpans[0]!.name).toBe('qwen-code.interaction');256 expect(mockSpans[0]!.parentContext).toEqual({ parent: 'daemon' });257 expect(mockSpans[0]!.attributes['session.id']).toBe('scoped-session');258 expect(mockSpans[0]!.attributes['qwen-code.message_type']).toBe(259 'acp_prompt',260 );261 expect(mockSpans[0]!.ended).toBe(true);262 expect(mockSpans[0]!.statuses.at(-1)?.code).toBe(SpanStatusCode.OK);263 });264 265 it('marks the interaction span ERROR when getResultStatus returns "error"', async () => {266 const config = createMockConfig();267 await withInteractionSpan(268 config,269 { promptId: 'p-cron-err', model: 'm', messageType: 'cron' },270 async () => 'done',271 () => 'error',272 );273 274 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');275 expect(span?.attributes['qwen-code.turn_status']).toBe('error');276 expect(span?.statuses.at(-1)?.code).toBe(SpanStatusCode.ERROR);277 });278 279 it('keeps a thrown error message instead of the generic error-status message', async () => {280 const config = createMockConfig();281 await expect(282 withInteractionSpan(283 config,284 { promptId: 'p-throw', model: 'm', messageType: 'cron' },285 async () => {286 throw new Error('boom from fn');287 },288 ),289 ).rejects.toThrow('boom from fn');290 291 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');292 expect(span?.statuses.at(-1)?.code).toBe(SpanStatusCode.ERROR);293 expect(span?.statuses.at(-1)?.message).toBe('boom from fn');294 });295 296 it('ends interaction span with error status', () => {297 const config = createMockConfig();298 startInteractionSpan(config, {299 promptId: 'prompt-2',300 model: 'test-model',301 messageType: 'userQuery',302 });303 304 endInteractionSpan('error', { errorMessage: 'something went wrong' });305 306 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.ERROR);307 expect(mockSpans[0]!.statuses[0]!.message).toBe('something went wrong');308 });309 310 it('ends interaction span with cancelled status as OK', () => {311 const config = createMockConfig();312 startInteractionSpan(config, {313 promptId: 'prompt-3',314 model: 'test-model',315 messageType: 'userQuery',316 });317 318 endInteractionSpan('cancelled');319 320 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.OK);321 });322 323 it('is idempotent — ending twice does not double-end', () => {324 const config = createMockConfig();325 startInteractionSpan(config, {326 promptId: 'prompt-4',327 model: 'test-model',328 messageType: 'userQuery',329 });330 331 endInteractionSpan('ok');332 endInteractionSpan('error');333 334 expect(mockSpans[0]!.statuses).toHaveLength(1);335 });336 337 it('no-ops when SDK is not initialized', () => {338 mockState.sdkInitialized = false;339 const config = createMockConfig();340 startInteractionSpan(config, {341 promptId: 'prompt-5',342 model: 'test-model',343 messageType: 'userQuery',344 });345 346 expect(mockSpans).toHaveLength(0);347 348 // endInteractionSpan should be safe to call349 endInteractionSpan('ok');350 });351 352 it('increments interaction sequence', () => {353 const config = createMockConfig();354 startInteractionSpan(config, {355 promptId: 'prompt-a',356 model: 'test-model',357 messageType: 'userQuery',358 });359 endInteractionSpan('ok');360 361 startInteractionSpan(config, {362 promptId: 'prompt-b',363 model: 'test-model',364 messageType: 'userQuery',365 });366 367 expect(mockSpans[1]!.attributes['interaction.sequence']).toBe(2);368 });369 370 it('records duration_ms and turn_status on end', () => {371 const config = createMockConfig();372 startInteractionSpan(config, {373 promptId: 'prompt-dur',374 model: 'test-model',375 messageType: 'userQuery',376 });377 378 endInteractionSpan('ok');379 380 const setAttrs = mockSpans[0]!.setAttributesCalls[0]!;381 expect(setAttrs).toHaveProperty('interaction.duration_ms');382 expect(setAttrs['qwen-code.turn_status']).toBe('ok');383 });384 });385 386 describe('interaction span — per-prompt traceId', () => {387 it('uses ROOT_CONTEXT as parent (each interaction is a trace root)', () => {388 setSessionContext(undefined, 'test-session');389 390 startInteractionSpan(createMockConfig({ sessionId: 'test-session' }), {391 promptId: 'p',392 model: 'm',393 messageType: 'userQuery',394 });395 396 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');397 expect(span?.parentContext).toBe(ROOT_CONTEXT);398 });399 400 it('ignores active OTel span — interaction always starts a new trace', () => {401 mockState.activeOtelSpan = { name: 'unrelated-wrapper-span' };402 403 startInteractionSpan(createMockConfig({ sessionId: 'test-session' }), {404 promptId: 'p',405 model: 'm',406 messageType: 'userQuery',407 });408 409 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');410 expect(span?.parentContext).toBe(ROOT_CONTEXT);411 });412 413 it('still stamps session.id attribute for cross-prompt correlation', () => {414 startInteractionSpan(createMockConfig({ sessionId: 'my-session' }), {415 promptId: 'p',416 model: 'm',417 messageType: 'userQuery',418 });419 420 const span = mockSpans.find((s) => s.name === 'qwen-code.interaction');421 expect(span?.attributes['session.id']).toBe('my-session');422 });423 });424 425 describe('LLM request spans', () => {426 it('creates and ends an LLM request span', () => {427 const span = startLLMRequestSpan('test-model', 'prompt-llm');428 429 expect(mockSpans).toHaveLength(1);430 expect(mockSpans[0]!.name).toBe('qwen-code.llm_request');431 expect(mockSpans[0]!.attributes['qwen-code.model']).toBe('test-model');432 433 endLLMRequestSpan(span, {434 success: true,435 inputTokens: 100,436 outputTokens: 50,437 durationMs: 500,438 });439 440 expect(mockSpans[0]!.ended).toBe(true);441 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.OK);442 });443 444 it('records error status on failure', () => {445 const span = startLLMRequestSpan('test-model', 'prompt-err');446 447 endLLMRequestSpan(span, {448 success: false,449 error: 'rate limited',450 });451 452 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.ERROR);453 expect(mockSpans[0]!.statuses[0]!.message).toBe('rate limited');454 });455 456 it('parents under interaction span when one is active', () => {457 const config = createMockConfig();458 startInteractionSpan(config, {459 promptId: 'p',460 model: 'm',461 messageType: 'userQuery',462 });463 464 const span = startLLMRequestSpan('m', 'p');465 endLLMRequestSpan(span, { success: true });466 endInteractionSpan('ok');467 468 // The LLM span should have a parent context469 const llmSpan = mockSpans.find((s) => s.name === 'qwen-code.llm_request');470 expect(llmSpan?.parentContext).toBeDefined();471 expect(llmSpan?.attributes['llm_request.context']).toBe('interaction');472 });473 474 it('marks standalone when no interaction is active', () => {475 const span = startLLMRequestSpan('m', 'p');476 endLLMRequestSpan(span, { success: true });477 478 expect(mockSpans[0]!.attributes['llm_request.context']).toBe(479 'standalone',480 );481 });482 483 it('LLM request span re-parents to active OTel span when no interaction is set (#4212)', () => {484 // Models a side-query LLM call running inside another OTel span (e.g.485 // an HTTP-instrumented span in a subagent path) — the new span must486 // attach to the active span instead of skipping back to session root,487 // otherwise the trace tree flattens.488 const fakeActive = { kind: 'fake-active-span' };489 mockState.activeOtelSpan = fakeActive;490 491 const span = startLLMRequestSpan('m', 'p');492 endLLMRequestSpan(span, { success: true });493 494 const llmSpan = mockSpans.find((s) => s.name === 'qwen-code.llm_request');495 expect(llmSpan?.parentContext).toMatchObject({496 __activeSpan: fakeActive,497 });498 // Without an explicit parent we still mark the call as standalone —499 // the OTel parent comes from instrumentation, not from interactionContext.500 expect(llmSpan?.attributes['llm_request.context']).toBe('standalone');501 });502 503 it('treats missing metadata as OK status', () => {504 const span = startLLMRequestSpan('test-model', 'prompt-no-meta');505 506 endLLMRequestSpan(span);507 508 expect(mockSpans[0]!.ended).toBe(true);509 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.OK);510 });511 512 it('returns NOOP span when SDK is not initialized', () => {513 mockState.sdkInitialized = false;514 const span = startLLMRequestSpan('m', 'p');515 expect(span.spanContext().traceId).toBe('0'.repeat(32));516 expect(span.spanContext().spanId).toBe('0'.repeat(16));517 518 // endLLMRequestSpan with noop should be safe519 endLLMRequestSpan(span, { success: true });520 });521 });522 523 describe('LLM request spans — Phase 4a (timing decomposition + GenAI dual-emit)', () => {524 it('startLLMRequestSpan dual-emits gen_ai.request.model alongside qwen-code.model', () => {525 const span = startLLMRequestSpan('test-model', 'p');526 endLLMRequestSpan(span, { success: true });527 528 const attrs = mockSpans[0]!.attributes;529 expect(attrs['qwen-code.model']).toBe('test-model');530 expect(attrs['gen_ai.request.model']).toBe('test-model');531 });532 533 it('endLLMRequestSpan dual-emits gen_ai.usage.input_tokens / output_tokens', () => {534 const span = startLLMRequestSpan('m', 'p');535 endLLMRequestSpan(span, {536 success: true,537 inputTokens: 100,538 outputTokens: 50,539 });540 541 const attrs = mockSpans[0]!.attributes;542 expect(attrs['input_tokens']).toBe(100);543 expect(attrs['gen_ai.usage.input_tokens']).toBe(100);544 expect(attrs['output_tokens']).toBe(50);545 expect(attrs['gen_ai.usage.output_tokens']).toBe(50);546 });547 548 it('endLLMRequestSpan dual-emits gen_ai.usage.cached_tokens when present', () => {549 const span = startLLMRequestSpan('m', 'p');550 endLLMRequestSpan(span, {551 success: true,552 inputTokens: 100,553 cachedInputTokens: 40,554 });555 556 const attrs = mockSpans[0]!.attributes;557 expect(attrs['cached_input_tokens']).toBe(40);558 expect(attrs['gen_ai.usage.cached_tokens']).toBe(40);559 });560 561 it('endLLMRequestSpan omits cached_input_tokens when undefined', () => {562 const span = startLLMRequestSpan('m', 'p');563 endLLMRequestSpan(span, { success: true, inputTokens: 100 });564 565 const attrs = mockSpans[0]!.attributes;566 expect(attrs['cached_input_tokens']).toBeUndefined();567 expect(attrs['gen_ai.usage.cached_tokens']).toBeUndefined();568 });569 570 it('endLLMRequestSpan emits cached_input_tokens === 0 (cache miss is meaningful info, not undefined)', () => {571 // Providers that report 0 cached tokens are signaling an explicit cache572 // miss. Distinct from undefined ("we don't know"). Both attribute names573 // must propagate the literal 0.574 const span = startLLMRequestSpan('m', 'p');575 endLLMRequestSpan(span, {576 success: true,577 inputTokens: 100,578 cachedInputTokens: 0,579 });580 581 const attrs = mockSpans[0]!.attributes;582 expect(attrs['cached_input_tokens']).toBe(0);583 expect(attrs['gen_ai.usage.cached_tokens']).toBe(0);584 });585 586 it('endLLMRequestSpan writes ttft_ms and dual-emits gen_ai.server.time_to_first_token (in seconds)', () => {587 const span = startLLMRequestSpan('m', 'p');588 endLLMRequestSpan(span, {589 success: true,590 ttftMs: 234,591 durationMs: 1000,592 });593 594 const attrs = mockSpans[0]!.attributes;595 expect(attrs['ttft_ms']).toBe(234);596 // Spec uses seconds as double — 234ms → 0.234s597 expect(attrs['gen_ai.server.time_to_first_token']).toBeCloseTo(0.234, 6);598 });599 600 it('endLLMRequestSpan omits ttft_ms when undefined (non-streaming or aborted before first chunk)', () => {601 const span = startLLMRequestSpan('m', 'p');602 endLLMRequestSpan(span, { success: true, durationMs: 500 });603 604 const attrs = mockSpans[0]!.attributes;605 expect(attrs['ttft_ms']).toBeUndefined();606 expect(attrs['gen_ai.server.time_to_first_token']).toBeUndefined();607 expect(attrs['sampling_ms']).toBeUndefined();608 expect(attrs['output_tokens_per_second']).toBeUndefined();609 });610 611 it('endLLMRequestSpan derives sampling_ms when ttftMs is set (no requestSetup)', () => {612 const span = startLLMRequestSpan('m', 'p');613 endLLMRequestSpan(span, {614 success: true,615 ttftMs: 200,616 durationMs: 1000,617 });618 619 // sampling_ms = duration - ttft = 1000 - 200 (setup is NOT subtracted —620 // duration_ms only covers ttft + sampling, never the setup phase that621 // precedes the span. See Phase 4b commit fixing the formula bug.)622 expect(mockSpans[0]!.attributes['sampling_ms']).toBe(800);623 });624 625 it('endLLMRequestSpan does NOT subtract requestSetupMs from sampling_ms (Phase 4b bug fix)', () => {626 // Phase 4a's formula `duration - ttft - setup` double-counted setup627 // because duration_ms ALREADY excludes setup (span starts after setup).628 // Phase 4b populates requestSetupMs with cumulative retry overhead —629 // if the formula still subtracted setup, sampling_ms would clamp to 0630 // for every retried request, wiping output-throughput data.631 const span = startLLMRequestSpan('m', 'p');632 endLLMRequestSpan(span, {633 success: true,634 ttftMs: 200,635 requestSetupMs: 300, // would yield 500 under old formula; we want 800636 durationMs: 1000,637 });638 639 expect(mockSpans[0]!.attributes['sampling_ms']).toBe(800);640 // request_setup_ms is still emitted as its own attribute — operators can641 // see the retry overhead AND the sampling time independently.642 expect(mockSpans[0]!.attributes['request_setup_ms']).toBe(300);643 });644 645 it('endLLMRequestSpan clamps sampling_ms to 0 when ttft exceeds duration (clock skew)', () => {646 const span = startLLMRequestSpan('m', 'p');647 endLLMRequestSpan(span, {648 success: true,649 ttftMs: 1500,650 durationMs: 1000,651 });652 653 // Math.max(0, 1000 - 1500) = 0 — only triggers when ttft > duration,654 // which in practice means clock drift or a measurement bug.655 expect(mockSpans[0]!.attributes['sampling_ms']).toBe(0);656 });657 658 it('endLLMRequestSpan derives output_tokens_per_second from sampling_ms + outputTokens', () => {659 const span = startLLMRequestSpan('m', 'p');660 endLLMRequestSpan(span, {661 success: true,662 ttftMs: 200,663 durationMs: 1200,664 outputTokens: 500,665 });666 667 // sampling_ms = 1000ms = 1s; otps = 500 / 1.0 = 500668 expect(mockSpans[0]!.attributes['sampling_ms']).toBe(1000);669 expect(mockSpans[0]!.attributes['output_tokens_per_second']).toBe(500);670 });671 672 it('endLLMRequestSpan rounds output_tokens_per_second to 2 decimals', () => {673 const span = startLLMRequestSpan('m', 'p');674 endLLMRequestSpan(span, {675 success: true,676 ttftMs: 200,677 durationMs: 1325, // sampling_ms = 1125678 outputTokens: 100, // otps = 100 / 1.125 = 88.888…679 });680 681 expect(mockSpans[0]!.attributes['output_tokens_per_second']).toBe(88.89);682 });683 684 it('endLLMRequestSpan omits output_tokens_per_second when sampling_ms == 0', () => {685 const span = startLLMRequestSpan('m', 'p');686 endLLMRequestSpan(span, {687 success: true,688 ttftMs: 1000,689 durationMs: 1000,690 outputTokens: 50,691 });692 693 // sampling_ms = 0 → otps would be Infinity, must be omitted694 expect(mockSpans[0]!.attributes['sampling_ms']).toBe(0);695 expect(696 mockSpans[0]!.attributes['output_tokens_per_second'],697 ).toBeUndefined();698 });699 700 it('endLLMRequestSpan omits output_tokens_per_second when outputTokens missing', () => {701 const span = startLLMRequestSpan('m', 'p');702 endLLMRequestSpan(span, {703 success: true,704 ttftMs: 200,705 durationMs: 1000,706 });707 708 expect(709 mockSpans[0]!.attributes['output_tokens_per_second'],710 ).toBeUndefined();711 });712 713 it('endLLMRequestSpan writes Phase 4b retry placeholders when caller provides them', () => {714 const span = startLLMRequestSpan('m', 'p');715 endLLMRequestSpan(span, {716 success: true,717 attempt: 3,718 requestSetupMs: 4500,719 retryTotalDelayMs: 4200,720 durationMs: 5000,721 });722 723 const attrs = mockSpans[0]!.attributes;724 expect(attrs['attempt']).toBe(3);725 expect(attrs['request_setup_ms']).toBe(4500);726 expect(attrs['retry_total_delay_ms']).toBe(4200);727 });728 729 it('endLLMRequestSpan omits Phase 4b fields when caller does not provide them (Phase 4a default)', () => {730 const span = startLLMRequestSpan('m', 'p');731 endLLMRequestSpan(span, { success: true, durationMs: 500 });732 733 const attrs = mockSpans[0]!.attributes;734 expect(attrs['attempt']).toBeUndefined();735 expect(attrs['request_setup_ms']).toBeUndefined();736 expect(attrs['retry_total_delay_ms']).toBeUndefined();737 });738 });739 740 describe('LLM request spans — response metadata & error enrichment', () => {741 it('endLLMRequestSpan dual-emits response_id / gen_ai.response.id', () => {742 const span = startLLMRequestSpan('m', 'p');743 endLLMRequestSpan(span, {744 success: true,745 responseId: 'chatcmpl-abc123',746 });747 748 const attrs = mockSpans[0]!.attributes;749 expect(attrs['response_id']).toBe('chatcmpl-abc123');750 expect(attrs['gen_ai.response.id']).toBe('chatcmpl-abc123');751 });752 753 it('endLLMRequestSpan omits response_id when undefined', () => {754 const span = startLLMRequestSpan('m', 'p');755 endLLMRequestSpan(span, { success: true });756 757 const attrs = mockSpans[0]!.attributes;758 expect(attrs['response_id']).toBeUndefined();759 expect(attrs['gen_ai.response.id']).toBeUndefined();760 });761 762 it('endLLMRequestSpan dual-emits finish_reason / gen_ai.response.finish_reasons (string vs array)', () => {763 const span = startLLMRequestSpan('m', 'p');764 endLLMRequestSpan(span, {765 success: true,766 finishReason: 'STOP',767 });768 769 const attrs = mockSpans[0]!.attributes;770 expect(attrs['finish_reason']).toBe('STOP');771 expect(attrs['gen_ai.response.finish_reasons']).toEqual(['STOP']);772 });773 774 it('endLLMRequestSpan omits finish_reason when undefined', () => {775 const span = startLLMRequestSpan('m', 'p');776 endLLMRequestSpan(span, { success: true });777 778 const attrs = mockSpans[0]!.attributes;779 expect(attrs['finish_reason']).toBeUndefined();780 expect(attrs['gen_ai.response.finish_reasons']).toBeUndefined();781 });782 783 it('endLLMRequestSpan dual-emits thoughts_token_count / gen_ai.usage.reasoning_tokens', () => {784 const span = startLLMRequestSpan('m', 'p');785 endLLMRequestSpan(span, {786 success: true,787 thoughtsTokenCount: 42,788 });789 790 const attrs = mockSpans[0]!.attributes;791 expect(attrs['thoughts_token_count']).toBe(42);792 expect(attrs['gen_ai.usage.reasoning_tokens']).toBe(42);793 });794 795 it('endLLMRequestSpan emits thoughts_token_count === 0 (no reasoning is meaningful info, not undefined)', () => {796 const span = startLLMRequestSpan('m', 'p');797 endLLMRequestSpan(span, {798 success: true,799 thoughtsTokenCount: 0,800 });801 802 const attrs = mockSpans[0]!.attributes;803 expect(attrs['thoughts_token_count']).toBe(0);804 expect(attrs['gen_ai.usage.reasoning_tokens']).toBe(0);805 });806 807 it('endLLMRequestSpan omits thoughts_token_count when undefined', () => {808 const span = startLLMRequestSpan('m', 'p');809 endLLMRequestSpan(span, { success: true });810 811 const attrs = mockSpans[0]!.attributes;812 expect(attrs['thoughts_token_count']).toBeUndefined();813 expect(attrs['gen_ai.usage.reasoning_tokens']).toBeUndefined();814 });815 816 it('endLLMRequestSpan emits subagent_name when present', () => {817 const span = startLLMRequestSpan('m', 'p');818 endLLMRequestSpan(span, {819 success: true,820 subagentName: 'Explore-abc123',821 });822 823 const attrs = mockSpans[0]!.attributes;824 expect(attrs['subagent_name']).toBe('Explore-abc123');825 });826 827 it('endLLMRequestSpan omits subagent_name when undefined', () => {828 const span = startLLMRequestSpan('m', 'p');829 endLLMRequestSpan(span, { success: true });830 831 expect(mockSpans[0]!.attributes['subagent_name']).toBeUndefined();832 });833 834 it('endLLMRequestSpan emits error_type and error.type on error spans', () => {835 const span = startLLMRequestSpan('m', 'p');836 endLLMRequestSpan(span, {837 success: false,838 error: 'API call failed',839 errorType: 'RateLimitError',840 errorStatusCode: 429,841 });842 843 const attrs = mockSpans[0]!.attributes;844 expect(attrs['error_type']).toBe('RateLimitError');845 expect(attrs['error.type']).toBe('RateLimitError');846 expect(attrs['error_status_code']).toBe(429);847 });848 849 it('endLLMRequestSpan omits error_type/error_status_code on success spans', () => {850 const span = startLLMRequestSpan('m', 'p');851 endLLMRequestSpan(span, { success: true });852 853 const attrs = mockSpans[0]!.attributes;854 expect(attrs['error_type']).toBeUndefined();855 expect(attrs['error.type']).toBeUndefined();856 expect(attrs['error_status_code']).toBeUndefined();857 });858 859 it('endLLMRequestSpan emits all new attributes together', () => {860 const span = startLLMRequestSpan('m', 'p');861 endLLMRequestSpan(span, {862 success: true,863 inputTokens: 500,864 outputTokens: 100,865 responseId: 'resp-xyz',866 finishReason: 'MAX_TOKENS',867 thoughtsTokenCount: 30,868 subagentName: 'code-reviewer',869 });870 871 const attrs = mockSpans[0]!.attributes;872 expect(attrs['response_id']).toBe('resp-xyz');873 expect(attrs['gen_ai.response.id']).toBe('resp-xyz');874 expect(attrs['finish_reason']).toBe('MAX_TOKENS');875 expect(attrs['gen_ai.response.finish_reasons']).toEqual(['MAX_TOKENS']);876 expect(attrs['thoughts_token_count']).toBe(30);877 expect(attrs['gen_ai.usage.reasoning_tokens']).toBe(30);878 expect(attrs['subagent_name']).toBe('code-reviewer');879 expect(attrs['input_tokens']).toBe(500);880 expect(attrs['output_tokens']).toBe(100);881 });882 });883 884 describe('LLM request spans — Phase 4c (recordApiRequestBreakdown wiring)', () => {885 beforeEach(() => {886 mockMetrics.recordApiRequestBreakdown.mockClear();887 });888 889 it('records all 3 phases when config + ttftMs + requestSetupMs are present', () => {890 const span = startLLMRequestSpan('test-model', 'p');891 const config = createMockConfig();892 endLLMRequestSpan(span, {893 success: true,894 durationMs: 1000,895 ttftMs: 200,896 requestSetupMs: 50,897 config,898 });899 900 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledTimes(3);901 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledWith(902 config,903 50,904 { model: 'test-model', phase: 'request_preparation' },905 );906 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledWith(907 config,908 200,909 { model: 'test-model', phase: 'network_latency' },910 );911 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledWith(912 config,913 800,914 { model: 'test-model', phase: 'response_processing' },915 );916 });917 918 it('skips metric recording when config is absent', () => {919 const span = startLLMRequestSpan('test-model', 'p');920 endLLMRequestSpan(span, {921 success: true,922 durationMs: 1000,923 ttftMs: 200,924 requestSetupMs: 50,925 });926 927 expect(mockMetrics.recordApiRequestBreakdown).not.toHaveBeenCalled();928 });929 930 it('skips metric recording when request failed (success=false)', () => {931 const span = startLLMRequestSpan('test-model', 'p');932 const config = createMockConfig();933 endLLMRequestSpan(span, {934 success: false,935 durationMs: 1000,936 ttftMs: 200,937 requestSetupMs: 50,938 config,939 });940 941 expect(mockMetrics.recordApiRequestBreakdown).not.toHaveBeenCalled();942 });943 944 it('records only REQUEST_PREPARATION when ttftMs is absent', () => {945 const span = startLLMRequestSpan('test-model', 'p');946 const config = createMockConfig();947 endLLMRequestSpan(span, {948 success: true,949 durationMs: 1000,950 requestSetupMs: 50,951 config,952 });953 954 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledTimes(1);955 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledWith(956 config,957 50,958 { model: 'test-model', phase: 'request_preparation' },959 );960 });961 962 it('skips RESPONSE_PROCESSING when samplingMs is 0 (ttftMs == duration)', () => {963 const span = startLLMRequestSpan('test-model', 'p');964 const config = createMockConfig();965 endLLMRequestSpan(span, {966 success: true,967 durationMs: 500,968 ttftMs: 500,969 config,970 });971 972 const calls = mockMetrics.recordApiRequestBreakdown.mock.calls;973 const phases = calls.map(974 (c: unknown[]) => (c[2] as { phase: string }).phase,975 );976 expect(phases).toContain('network_latency');977 expect(phases).not.toContain('response_processing');978 });979 980 it('idempotency — second endLLMRequestSpan call does not record again', () => {981 const span = startLLMRequestSpan('test-model', 'p');982 const config = createMockConfig();983 const metadata = {984 success: true,985 durationMs: 1000,986 ttftMs: 200,987 requestSetupMs: 50,988 config,989 };990 endLLMRequestSpan(span, metadata);991 endLLMRequestSpan(span, metadata);992 993 // Only first call records (3 phases), second is short-circuited.994 expect(mockMetrics.recordApiRequestBreakdown).toHaveBeenCalledTimes(3);995 });996 });997 998 describe('tool spans', () => {999 it('creates and ends a tool span', () => {1000 const span = startToolSpan('ReadFile', { 'tool.call_id': 'call-1' });1001 1002 expect(mockSpans).toHaveLength(1);1003 expect(mockSpans[0]!.name).toBe('qwen-code.tool');1004 expect(mockSpans[0]!.attributes['tool.name']).toBe('ReadFile');1005 expect(mockSpans[0]!.attributes['tool.call_id']).toBe('call-1');1006 1007 endToolSpan(span, { success: true });1008 1009 expect(mockSpans[0]!.ended).toBe(true);1010 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.OK);1011 });1012 1013 it('records error on tool failure', () => {1014 const span = startToolSpan('Bash');1015 endToolSpan(span, { success: false, error: 'command failed' });1016 1017 expect(mockSpans[0]!.statuses[0]!.code).toBe(SpanStatusCode.ERROR);1018 expect(mockSpans[0]!.statuses[0]!.message).toBe('command failed');1019 });1020 1021 it('does not set status when no metadata is passed', () => {1022 const span = startToolSpan('Read');1023 endToolSpan(span);1024 1025 expect(mockSpans[0]!.statuses).toHaveLength(0);1026 });1027 1028 it('tool span re-parents to active OTel span when no interaction is set (#4212)', () => {1029 const fakeActive = { kind: 'fake-active-span' };1030 mockState.activeOtelSpan = fakeActive;1031 1032 const span = startToolSpan('Bash');1033 endToolSpan(span, { success: true });1034 1035 const toolSpan = mockSpans.find((s) => s.name === 'qwen-code.tool');1036 expect(toolSpan?.parentContext).toMatchObject({1037 __activeSpan: fakeActive,1038 });1039 });1040 1041 it('concurrent tool spans are isolated', () => {1042 const config = createMockConfig();1043 startInteractionSpan(config, {1044 promptId: 'p',1045 model: 'm',1046 messageType: 'userQuery',1047 });1048 1049 const span1 = startToolSpan('Read', { 'tool.call_id': 'c1' });1050 const span2 = startToolSpan('Bash', { 'tool.call_id': 'c2' });1051 1052 // End span2 first (out of order)1053 endToolSpan(span2, { success: true });1054 endToolSpan(span1, { success: false, error: 'timeout' });1055 1056 // Find tool spans1057 const toolSpans = mockSpans.filter((s) => s.name === 'qwen-code.tool');1058 expect(toolSpans).toHaveLength(2);1059 1060 const readSpan = toolSpans.find(1061 (s) => s.attributes['tool.name'] === 'Read',1062 );1063 const bashSpan = toolSpans.find(1064 (s) => s.attributes['tool.name'] === 'Bash',1065 );1066 1067 expect(bashSpan?.statuses[0]?.code).toBe(SpanStatusCode.OK);1068 expect(readSpan?.statuses[0]?.code).toBe(SpanStatusCode.ERROR);1069 expect(readSpan?.statuses[0]?.message).toBe('timeout');1070 });1071 });1072 1073 describe('session.id derives from the owning session, not the process-global (#4602 review)', () => {1074 it('stamps a tool span with the interaction session.id even when the process-global belongs to another session', () => {1075 // Daemon scenario: telemetry init left the process-global pointing at1076 // session B, but the active interaction belongs to session A.1077 setSessionContext(undefined, 'session-B-global');1078 startInteractionSpan(createMockConfig({ sessionId: 'session-A' }), {1079 promptId: 'p-a',1080 model: 'm',1081 messageType: 'acp_prompt',1082 });1083 1084 const span = startToolSpan('Bash', { 'tool.call_id': 'c1' });1085 endToolSpan(span, { success: true });1086 1087 const toolSpan = mockSpans.find((s) => s.name === 'qwen-code.tool');1088 expect(toolSpan?.attributes['session.id']).toBe('session-A');1089 });1090 1091 it('stamps an llm_request span with the interaction session.id, not the global', () => {1092 setSessionContext(undefined, 'session-B-global');1093 startInteractionSpan(createMockConfig({ sessionId: 'session-A' }), {1094 promptId: 'p-a',1095 model: 'm',1096 messageType: 'acp_prompt',1097 });1098 1099 const span = startLLMRequestSpan('m', 'p-a');1100 endLLMRequestSpan(span, { success: true });1101 1102 const llmSpan = mockSpans.find((s) => s.name === 'qwen-code.llm_request');1103 expect(llmSpan?.attributes['session.id']).toBe('session-A');1104 });1105 1106 it('stamps a tool.execution span with the owning session id via the tool span context', () => {1107 setSessionContext(undefined, 'session-B-global');1108 startInteractionSpan(createMockConfig({ sessionId: 'session-A' }), {1109 promptId: 'p-a',1110 model: 'm',1111 messageType: 'acp_prompt',1112 });1113 1114 const toolSpan = startToolSpan('Bash', { 'tool.call_id': 'c1' });1115 let execSpan!: ReturnType<typeof startToolExecutionSpan>;1116 runInToolSpanContext(toolSpan, () => {1117 execSpan = startToolExecutionSpan();1118 });1119 endToolExecutionSpan(execSpan, { success: true });1120 endToolSpan(toolSpan, { success: true });1121 1122 const exec = mockSpans.find((s) => s.name === 'qwen-code.tool.execution');1123 expect(exec?.attributes['session.id']).toBe('session-A');1124 });1125 1126 it('stamps a blocked-on-user span with the owning session id via the tool parent', () => {1127 setSessionContext(undefined, 'session-B-global');1128 startInteractionSpan(createMockConfig({ sessionId: 'session-A' }), {1129 promptId: 'p-a',1130 model: 'm',1131 messageType: 'acp_prompt',1132 });1133 1134 const toolSpan = startToolSpan('Bash', { 'tool.call_id': 'c1' });1135 const blockedSpan = startToolBlockedOnUserSpan(toolSpan, {1136 call_id: 'c1',1137 });1138 endToolBlockedOnUserSpan(blockedSpan, { decision: 'proceed_once' });1139 endToolSpan(toolSpan, { success: true });1140 1141 const blocked = mockSpans.find(1142 (s) => s.name === 'qwen-code.tool.blocked_on_user',1143 );1144 expect(blocked?.attributes['session.id']).toBe('session-A');1145 });1146 1147 it('stamps a hook span with the owning session id via the logical parent', () => {1148 setSessionContext(undefined, 'session-B-global');1149 startInteractionSpan(createMockConfig({ sessionId: 'session-A' }), {1150 promptId: 'p-a',1151 model: 'm',1152 messageType: 'acp_prompt',1153 });1154 1155 const toolSpan = startToolSpan('Bash', { 'tool.call_id': 'c1' });1156 let hookSpan!: ReturnType<typeof startHookSpan>;1157 runInToolSpanContext(toolSpan, () => {1158 hookSpan = startHookSpan({1159 hookEvent: 'PreToolUse',1160 toolName: 'Bash',1161 toolUseId: 'use-1',1162 });1163 });1164 endHookSpan(hookSpan, { success: true, shouldProceed: true });1165 endToolSpan(toolSpan, { success: true });1166 1167 const hook = mockSpans.find((s) => s.name === 'qwen-code.hook');1168 expect(hook?.attributes['session.id']).toBe('session-A');1169 });1170 1171 it('isolates concurrent sessions: each tool span carries its own session id', async () => {1172 // Two interactions for two different sessions while the global is stale.1173 setSessionContext(undefined, 'stale-global');1174 1175 await withInteractionSpan(1176 createMockConfig({ sessionId: 'session-A' }),1177 { promptId: 'pa', model: 'm', messageType: 'acp_prompt' },1178 async () => {1179 endToolSpan(startToolSpan('Read', { 'tool.call_id': 'a1' }), {1180 success: true,1181 });1182 },1183 );1184 await withInteractionSpan(1185 createMockConfig({ sessionId: 'session-B' }),1186 { promptId: 'pb', model: 'm', messageType: 'acp_prompt' },1187 async () => {1188 endToolSpan(startToolSpan('Write', { 'tool.call_id': 'b1' }), {1189 success: true,1190 });1191 },1192 );1193 1194 const readSpan = mockSpans.find(1195 (s) => s.attributes['tool.name'] === 'Read',1196 );1197 const writeSpan = mockSpans.find(1198 (s) => s.attributes['tool.name'] === 'Write',1199 );1200 expect(readSpan?.attributes['session.id']).toBe('session-A');