diff --git a/packages/core/src/core/coreToolScheduler.test.ts b/packages/core/src/core/coreToolScheduler.test.ts index 182cc675d26..ec9be0ce3d5 100644 --- a/packages/core/src/core/coreToolScheduler.test.ts +++ b/packages/core/src/core/coreToolScheduler.test.ts @@ -64,9 +64,9 @@ type ToolSpanRecord = { ended: boolean; /** * Metadata passed to endToolSpan / endToolExecutionSpan — captured so - * tests can assert success/error values are forwarded correctly. + * tests can assert success/error/cancelled values are forwarded correctly. */ - endMetadata?: { success?: boolean; error?: string }; + endMetadata?: { success?: boolean; error?: string; cancelled?: boolean }; }; const toolSpanRecords = vi.hoisted((): ToolSpanRecord[] => []); @@ -154,7 +154,7 @@ vi.mock('../telemetry/session-tracing.js', () => ({ endToolExecutionSpan: vi.fn( ( span: ToolSpanRecord & ReturnType, - metadata?: { success?: boolean; error?: string }, + metadata?: { success?: boolean; error?: string; cancelled?: boolean }, ) => { if (metadata) { span.endMetadata = metadata; @@ -1982,6 +1982,22 @@ describe('CoreToolScheduler cancellation during executing with live output', () // eslint-disable-next-line @typescript-eslint/no-explicit-any const cancelled: any = completedCalls[0]; expect(cancelled.response.resultDisplay).toBe('hello'); + + // #4212: When the tool resolves cleanly after observing signal.aborted, + // the execution sub-span must end as not-success (cancelled) so it + // agrees with the parent tool span instead of misreporting success + // alongside a cancelled parent. `toolSpanRecords` accumulates across + // tests in this describe scope, so search the most recent record. + const execSpanRecord = toolSpanRecords.findLast( + (s) => s.name === 'tool.execution', + ); + expect(execSpanRecord?.endMetadata?.success).toBe(false); + expect(execSpanRecord?.endMetadata?.error).toBe( + 'Tool execution cancelled by user', + ); + // #4302 review: cancelled: true so the exec sub-span ends UNSET (not + // ERROR) — matches setToolSpanCancelled on the parent tool span. + expect(execSpanRecord?.endMetadata?.cancelled).toBe(true); }); }); @@ -3716,7 +3732,9 @@ describe('CoreToolScheduler telemetry spans', () => { const exec = getExecutionSpan(); expect(exec).toBeDefined(); expect(exec!.ended).toBe(true); - expect(exec!.endMetadata).toEqual({ success: true }); + // cancelled: false because signal is not aborted on the success path + // (#4302 review: cancelled flag now propagates through endToolExecutionSpan). + expect(exec!.endMetadata).toEqual({ success: true, cancelled: false }); }); it('execution sub-span: ended (success: false) when ToolResult.error is set', async () => { @@ -3733,7 +3751,16 @@ describe('CoreToolScheduler telemetry spans', () => { const exec = getExecutionSpan(); expect(exec).toBeDefined(); expect(exec!.ended).toBe(true); - expect(exec!.endMetadata).toEqual({ success: false }); + // Since #4212 the success path also stamps a sanitized `error` reason on + // the exec span when ToolResult.error is set, so trace backends can + // distinguish a failed-result close from a cancelled one without + // cross-referencing the parent tool span. cancelled: false since the + // signal isn't aborted (#4302 review). + expect(exec!.endMetadata).toEqual({ + success: false, + error: 'Tool execution failed', + cancelled: false, + }); }); it('execution sub-span: ended (success: false) with sanitized error on thrown invocation exception', async () => { @@ -3780,6 +3807,20 @@ describe('CoreToolScheduler telemetry spans', () => { // Operators filtering exec spans for errors should NOT see cancellation // messages here — only real exception messages. expect(exec!.endMetadata?.error).toBe('Tool execution cancelled by user'); + // #4302 review: catch-path cancellation also threads cancelled: true so + // the exec sub-span lands UNSET, not ERROR. + expect(exec!.endMetadata?.cancelled).toBe(true); + }); + + it('execution sub-span: cancelled flag is NOT set on real exceptions (#4302)', async () => { + await runSingleTool({ + execute: vi.fn().mockRejectedValue(new Error('boom')), + }); + const exec = getExecutionSpan(); + expect(exec).toBeDefined(); + // signal not aborted — this is a real exception, must surface as ERROR + // status. cancelled stays falsy. + expect(exec!.endMetadata?.cancelled).toBeFalsy(); }); }); diff --git a/packages/core/src/core/coreToolScheduler.ts b/packages/core/src/core/coreToolScheduler.ts index 072fd2c0485..2138a84c91c 100644 --- a/packages/core/src/core/coreToolScheduler.ts +++ b/packages/core/src/core/coreToolScheduler.ts @@ -2033,10 +2033,23 @@ export class CoreToolScheduler { } const toolResult: ToolResult = await promise; + // A tool that observes signal.aborted and resolves with a normal + // ToolResult (no .error field) would otherwise close the execution + // sub-span as success while the parent tool span ends as cancelled. + // Mirror the abort signal here — and pass `cancelled: true` so the + // exec sub-span ends UNSET, matching setToolSpanCancelled on the + // parent (#4212, #4302 review). + const aborted = signal.aborted; endToolExecutionSpan(execSpan, { - success: toolResult.error === undefined, + success: toolResult.error === undefined && !aborted, + error: aborted + ? TOOL_SPAN_STATUS_TOOL_CANCELLED + : toolResult.error + ? TOOL_SPAN_STATUS_TOOL_ERROR + : undefined, + cancelled: aborted, }); - if (signal.aborted) { + if (aborted) { // PostToolUseFailure Hook let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { @@ -2288,15 +2301,18 @@ export class CoreToolScheduler { // Distinguish user cancellation from real tool exceptions on the // execution sub-span so trace backends filtering for errors do not // see false positives. Both are still success: false; only the - // sanitized error message differs. + // sanitized error message and (for cancellation) the UNSET status + // differ. + const aborted = signal.aborted; endToolExecutionSpan(execSpan, { success: false, - error: signal.aborted + error: aborted ? TOOL_SPAN_STATUS_TOOL_CANCELLED : TOOL_SPAN_STATUS_TOOL_EXCEPTION, + cancelled: aborted, }); - if (signal.aborted) { + if (aborted) { // PostToolUseFailure Hook (user interrupt) let cancelMessage = 'User cancelled tool execution.'; if (hooksEnabled && messageBus) { diff --git a/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts b/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts index aaf3e1b2071..90821c6184c 100644 --- a/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts +++ b/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.test.ts @@ -108,6 +108,7 @@ vi.mock('@opentelemetry/api', async (importOriginal) => { vi.mock('../../telemetry/tracer.js', () => ({ API_CALL_FAILED_SPAN_STATUS_MESSAGE: 'API call failed', + API_CALL_ABORTED_SPAN_STATUS_MESSAGE: 'API call aborted', })); vi.mock('../../telemetry/index.js', () => { @@ -1096,6 +1097,182 @@ describe('LoggingContentGenerator', () => { expect(spanRecord.ended).toBe(true); }); + it('skips success api_response log when stream span is ended by idle timeout (#4212)', async () => { + // The 5-min idle timeout would otherwise leave a contradictory pair of + // signals during incident response: the span says "timed out / error" + // while the api_response log says "success". We capture the idle-timeout + // callback through a setTimeout spy and invoke it manually — fake timers + // interact poorly with async-generator iteration. + const STREAM_IDLE_TIMEOUT_MS = 5 * 60_000; + let idleCallback: (() => void) | undefined; + const realSetTimeout = global.setTimeout; + type SetTimeoutArgs = Parameters; + const setTimeoutSpy = vi.spyOn(global, 'setTimeout').mockImplementation((( + ...args: SetTimeoutArgs + ) => { + const [cb, ms] = args; + if (ms === STREAM_IDLE_TIMEOUT_MS) { + idleCallback = cb as () => void; + return { unref: () => {} } as unknown as ReturnType; + } + return realSetTimeout(...args); + }) as typeof setTimeout); + + try { + let releaseStream: (() => void) | undefined; + // Set up the gate BEFORE the first yield so the outer test can + // release us as soon as it reads the first chunk. + const gate = new Promise((resolve) => { + releaseStream = resolve; + }); + const response1 = createResponse('resp-idle', 'model-stream', [ + { text: 'partial' }, + ]); + const wrapped = createWrappedGenerator( + vi.fn(), + vi.fn().mockResolvedValue( + (async function* () { + yield response1; + // Pause until the test releases us — meanwhile the idle timer + // fires and ends the span as failed. + await gate; + })(), + ), + ); + // Enable OpenAI logging so we can verify the post-loop OpenAI + // interaction log is also gated by spanEndedByTimeout — without this, + // safelyLogOpenAIInteraction short-circuits unconditionally and the + // skip behavior would go untested. + const generator = new LoggingContentGenerator(wrapped, createConfig(), { + model: 'test-model', + authType: AuthType.USE_OPENAI, + enableOpenAILogging: true, + }); + const openaiLoggerInstance = vi.mocked(OpenAILogger).mock.results.at(-1) + ?.value as { logInteraction: ReturnType }; + + const request = { + model: 'test-model', + contents: 'Hello', + } as unknown as GenerateContentParameters; + + const stream = await generator.generateContentStream( + request, + 'prompt-idle-timeout', + ); + const iterator = stream[Symbol.asyncIterator](); + + const first = await iterator.next(); + expect(first.done).toBe(false); + expect(idleCallback).toBeDefined(); + + // Fire the idle timeout — span should end as timed-out. + idleCallback?.(); + + const spanRecord = getStreamSpanRecord(); + expect(spanRecord.attributes['stream.timed_out']).toBe(true); + expect(spanRecord.endMetadata?.success).toBe(false); + expect(spanRecord.endMetadata?.error).toBe( + 'Stream span timed out (idle)', + ); + expect(spanRecord.ended).toBe(true); + + releaseStream?.(); + const done = await iterator.next(); + expect(done.done).toBe(true); + + // Despite the stream completing cleanly afterwards, no success-flavored + // api_response or OpenAI-interaction log should have been emitted — + // the span's timeout state is the canonical signal. + expect(logApiResponse).not.toHaveBeenCalled(); + expect(openaiLoggerInstance.logInteraction).not.toHaveBeenCalled(); + } finally { + setTimeoutSpy.mockRestore(); + } + }); + + it('skips api_error log when stream throws after idle timeout already closed the span (#4302)', async () => { + // Same gating as the success path: when the 5-min idle timeout already + // closed the LLM span as failed, a downstream throw must not emit an + // api_error log either, otherwise telemetry shows "span timed-out + log + // api_error" — the contradictory pair the timeout fix targets. + const STREAM_IDLE_TIMEOUT_MS = 5 * 60_000; + let idleCallback: (() => void) | undefined; + const realSetTimeout = global.setTimeout; + type SetTimeoutArgs = Parameters; + const setTimeoutSpy = vi.spyOn(global, 'setTimeout').mockImplementation((( + ...args: SetTimeoutArgs + ) => { + const [cb, ms] = args; + if (ms === STREAM_IDLE_TIMEOUT_MS) { + idleCallback = cb as () => void; + return { unref: () => {} } as unknown as ReturnType; + } + return realSetTimeout(...args); + }) as typeof setTimeout); + + try { + let releaseStream: (() => void) | undefined; + const gate = new Promise((resolve) => { + releaseStream = resolve; + }); + const response1 = createResponse('resp-throw', 'model-stream', [ + { text: 'partial' }, + ]); + const downstreamError = new Error('upstream-fail'); + const wrapped = createWrappedGenerator( + vi.fn(), + vi.fn().mockResolvedValue( + (async function* () { + yield response1; + await gate; + throw downstreamError; + })(), + ), + ); + const generator = new LoggingContentGenerator(wrapped, createConfig(), { + model: 'test-model', + authType: AuthType.USE_OPENAI, + enableOpenAILogging: true, + }); + const openaiLoggerInstance = vi.mocked(OpenAILogger).mock.results.at(-1) + ?.value as { logInteraction: ReturnType }; + + const request = { + model: 'test-model', + contents: 'Hello', + } as unknown as GenerateContentParameters; + + const stream = await generator.generateContentStream( + request, + 'prompt-throw-after-timeout', + ); + const iterator = stream[Symbol.asyncIterator](); + + const first = await iterator.next(); + expect(first.done).toBe(false); + expect(idleCallback).toBeDefined(); + + // Fire idle timeout — span is now closed as timed-out. + idleCallback?.(); + + // Now release the stream and let it throw. + releaseStream?.(); + await expect(iterator.next()).rejects.toThrow('upstream-fail'); + + const spanRecord = getStreamSpanRecord(); + expect(spanRecord.endMetadata?.error).toBe( + 'Stream span timed out (idle)', + ); + // Neither error-flavored telemetry path should fire — the span's + // timeout state is the canonical signal. + expect(logApiError).not.toHaveBeenCalled(); + expect(openaiLoggerInstance.logInteraction).not.toHaveBeenCalled(); + } finally { + setTimeoutSpy.mockRestore(); + } + }); + it('preserves stream errors when error logging fails', async () => { const response1 = createResponse('resp-1', 'model-stream', [ { text: 'partial' }, diff --git a/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts b/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts index b1718772a7a..25a3adb03b5 100644 --- a/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts +++ b/packages/core/src/core/loggingContentGenerator/loggingContentGenerator.ts @@ -520,47 +520,61 @@ export class LoggingContentGenerator implements ContentGenerator { const streamResponseText = isInternal ? undefined : this.extractResponseText(consolidatedResponse); - runInSpan(() => - this.safelyLogApiResponse( - firstResponseId, - durationMs, - firstModelVersion || model, - userPromptId, - lastUsageMetadata, - streamResponseText, - ), - ); - if (!isInternal && span) { - addModelOutputAttributes(this.config, span, streamResponseText); + // If the idle timeout already closed the span as failed, do not contradict + // it with a "success" api_response log or model-output span attributes. + // The OpenAI interaction log is also skipped — telemetry already carries + // the timeout signal and a parallel "success" record would be confusing + // during incident response (#4212). + if (!spanEndedByTimeout) { + runInSpan(() => + this.safelyLogApiResponse( + firstResponseId, + durationMs, + firstModelVersion || model, + userPromptId, + lastUsageMetadata, + streamResponseText, + ), + ); + if (!isInternal && span) { + addModelOutputAttributes(this.config, span, streamResponseText); + } + await runInSpan(() => + this.safelyLogOpenAIInteraction( + openaiRequest, + consolidatedResponse, + undefined, + userPromptId, + ), + ); } - await runInSpan(() => - this.safelyLogOpenAIInteraction( - openaiRequest, - consolidatedResponse, - undefined, - userPromptId, - ), - ); } catch (error) { errorOccurred = true; - const durationMs = Date.now() - startTime; - runInSpan(() => - this.safelyLogApiError( - firstResponseId, - durationMs, - error, - firstModelVersion || model, - userPromptId, - ), - ); - await runInSpan(() => - this.safelyLogOpenAIInteraction( - openaiRequest, - undefined, - error, - userPromptId, - ), - ); + // Same gating as the success path above: if the idle timeout already + // closed the span as failed, do not emit a parallel api_error log + // (the span is the canonical signal). Otherwise we'd produce the + // exact contradictory pair the timeout fix targets — span timed-out + // + api_error log — just on the error branch (#4302 review). + if (!spanEndedByTimeout) { + const durationMs = Date.now() - startTime; + runInSpan(() => + this.safelyLogApiError( + firstResponseId, + durationMs, + error, + firstModelVersion || model, + userPromptId, + ), + ); + await runInSpan(() => + this.safelyLogOpenAIInteraction( + openaiRequest, + undefined, + error, + userPromptId, + ), + ); + } throw error; } finally { if (spanEndTimeout !== undefined) { diff --git a/packages/core/src/telemetry/session-tracing.test.ts b/packages/core/src/telemetry/session-tracing.test.ts index 64fd95862d8..608aa859160 100644 --- a/packages/core/src/telemetry/session-tracing.test.ts +++ b/packages/core/src/telemetry/session-tracing.test.ts @@ -13,6 +13,10 @@ const mockState = vi.hoisted(() => ({ // try/catch hardening in end*Span helpers (span.end() must still run). throwOnSetAttributes: false, throwOnSetStatus: false, + // When set, `context.active()` returns a context that carries this fake + // span and `trace.getSpan()` reports it. Lets tests exercise the + // active-OTel-span fallback in resolveParentContext (#4212). + activeOtelSpan: undefined as unknown, })); vi.mock('./sdk.js', () => ({ @@ -101,10 +105,17 @@ vi.mock('@opentelemetry/api', async () => { ...(ctx as object), __parentSpan: _span, }), + getSpan: (ctx: unknown) => + typeof ctx === 'object' && ctx !== null && '__activeSpan' in ctx + ? (ctx as { __activeSpan: unknown }).__activeSpan + : undefined, wrapSpanContext: actual.trace.wrapSpanContext, }, context: { - active: () => ({}), + active: () => + mockState.activeOtelSpan + ? { __activeSpan: mockState.activeOtelSpan } + : {}, with: (_ctx: unknown, fn: () => T): T => fn(), }, }; @@ -144,6 +155,7 @@ describe('session-tracing', () => { mockState.sdkInitialized = true; mockState.throwOnSetAttributes = false; mockState.throwOnSetStatus = false; + mockState.activeOtelSpan = undefined; }); afterEach(() => { @@ -320,6 +332,26 @@ describe('session-tracing', () => { ); }); + it('LLM request span re-parents to active OTel span when no interaction is set (#4212)', () => { + // Models a side-query LLM call running inside another OTel span (e.g. + // an HTTP-instrumented span in a subagent path) — the new span must + // attach to the active span instead of skipping back to session root, + // otherwise the trace tree flattens. + const fakeActive = { kind: 'fake-active-span' }; + mockState.activeOtelSpan = fakeActive; + + const span = startLLMRequestSpan('m', 'p'); + endLLMRequestSpan(span, { success: true }); + + const llmSpan = mockSpans.find((s) => s.name === 'qwen-code.llm_request'); + expect(llmSpan?.parentContext).toMatchObject({ + __activeSpan: fakeActive, + }); + // Without an explicit parent we still mark the call as standalone — + // the OTel parent comes from instrumentation, not from interactionContext. + expect(llmSpan?.attributes['llm_request.context']).toBe('standalone'); + }); + it('treats missing metadata as OK status', () => { const span = startLLMRequestSpan('test-model', 'prompt-no-meta'); @@ -370,6 +402,19 @@ describe('session-tracing', () => { expect(mockSpans[0]!.statuses).toHaveLength(0); }); + it('tool span re-parents to active OTel span when no interaction is set (#4212)', () => { + const fakeActive = { kind: 'fake-active-span' }; + mockState.activeOtelSpan = fakeActive; + + const span = startToolSpan('Bash'); + endToolSpan(span, { success: true }); + + const toolSpan = mockSpans.find((s) => s.name === 'qwen-code.tool'); + expect(toolSpan?.parentContext).toMatchObject({ + __activeSpan: fakeActive, + }); + }); + it('concurrent tool spans are isolated', () => { const config = createMockConfig(); startInteractionSpan(config, { @@ -429,6 +474,19 @@ describe('session-tracing', () => { expect(execSpan.spanContext().traceId).toBe('0'.repeat(32)); }); + it('tool execution span re-parents to active OTel span when no toolContext is set (#4212)', () => { + const fakeActive = { kind: 'fake-active-span' }; + mockState.activeOtelSpan = fakeActive; + + const execSpan = startToolExecutionSpan(); + endToolExecutionSpan(execSpan, { success: true }); + + const span = mockSpans.find((s) => s.name === 'qwen-code.tool.execution'); + expect(span?.parentContext).toMatchObject({ + __activeSpan: fakeActive, + }); + }); + it('falls back gracefully when no tool span is active', () => { const execSpan = startToolExecutionSpan(); @@ -438,6 +496,45 @@ describe('session-tracing', () => { endToolExecutionSpan(execSpan, { success: true }); expect(mockSpans[0]!.ended).toBe(true); }); + + it('cancelled: true keeps status UNSET while still recording attributes (#4302)', () => { + const execSpan = startToolExecutionSpan(); + endToolExecutionSpan(execSpan, { + success: false, + error: 'Tool execution cancelled by user', + cancelled: true, + }); + + const record = mockSpans.find( + (s) => s.name === 'qwen-code.tool.execution', + ); + expect(record?.ended).toBe(true); + // No setStatus call — status stays UNSET, matching setToolSpanCancelled + // on the parent tool span. Without this, success: false would set ERROR + // and trace backends filtering for errors would false-positive on + // user cancellations. + expect(record?.statuses).toHaveLength(0); + // Attributes still record the cancellation reason. + expect(record?.attributes['success']).toBe(false); + expect(record?.attributes['error']).toBe( + 'Tool execution cancelled by user', + ); + }); + + it('cancelled: false (default) still maps success: false to ERROR status', () => { + const execSpan = startToolExecutionSpan(); + endToolExecutionSpan(execSpan, { + success: false, + error: 'Tool execution failed', + }); + + const record = mockSpans.find( + (s) => s.name === 'qwen-code.tool.execution', + ); + expect(record?.statuses).toHaveLength(1); + expect(record?.statuses[0]!.code).toBe(SpanStatusCode.ERROR); + expect(record?.statuses[0]!.message).toBe('Tool execution failed'); + }); }); describe('toolContext ALS lifecycle', () => { diff --git a/packages/core/src/telemetry/session-tracing.ts b/packages/core/src/telemetry/session-tracing.ts index b73bd4083cf..d750a8cf349 100644 --- a/packages/core/src/telemetry/session-tracing.ts +++ b/packages/core/src/telemetry/session-tracing.ts @@ -11,6 +11,7 @@ import { SpanStatusCode, trace, type Attributes, + type Context, type Span, } from '@opentelemetry/api'; import type { Config } from '../config/config.js'; @@ -70,6 +71,39 @@ interface SpanContext { | 'hook'; } +/** + * Resolve the parent OTel Context for a new span. + * + * Priority: + * 1. Explicit parent (from `interactionContext` / `toolContext` ALS) — keeps + * the LLM/tool/exec span attached to its logical owner. + * 2. Currently-active OTel span — preserves the trace tree when an + * LLM or tool call is nested inside another span (e.g. subagent inside a + * tool, or any nested-tool path) but the ALS parent has already exited. + * Without this, the new span re-parents to the synthetic session root and + * the trace flattens. + * 3. Synthetic session-root context — keeps side-query spans (auto-title, + * recap, etc.) correlated with the session even when they run outside + * any interaction. + * 4. Active context as a no-op fallback. + * + * Mirrors `tracer.ts:getParentContext()` (#4126 review follow-up, #4212). + * + * SYNC: keep parent-resolution logic in step with getParentContext() in + * telemetry/tracer.ts — drift here re-introduces the trace-tree flattening + * issue #4212 set out to fix (#4302 review). + */ +function resolveParentContext(parent: SpanContext | undefined): Context { + if (parent) { + return trace.setSpan(otelContext.active(), parent.span); + } + const active = otelContext.active(); + if (trace.getSpan(active)) { + return active; + } + return getSessionContext() ?? active; +} + const NOOP_SPAN = trace.wrapSpanContext({ traceId: '0'.repeat(32), spanId: '0'.repeat(16), @@ -198,13 +232,10 @@ export function startLLMRequestSpan(model: string, promptId: string): Span { } const parentCtx = interactionContext.getStore(); - // Fall back to session root context (deterministic traceId from sessionId) - // for side-query LLM calls (auto-title, recap, etc.) that run outside an - // interaction. Without this, those spans start a fresh trace and lose - // correlation with the session. - const ctx = parentCtx - ? trace.setSpan(otelContext.active(), parentCtx.span) - : (getSessionContext() ?? otelContext.active()); + // resolveParentContext() also re-parents to the active OTel span when + // present, so a side-query LLM call nested inside a tool span still + // attaches to the tool span instead of skipping back to the session root. + const ctx = resolveParentContext(parentCtx); const attributes: Attributes = { 'qwen-code.model': model, @@ -298,10 +329,9 @@ export function startToolSpan( } const parentCtx = interactionContext.getStore(); - // Same session-root fallback as startLLMRequestSpan. - const ctx = parentCtx - ? trace.setSpan(otelContext.active(), parentCtx.span) - : (getSessionContext() ?? otelContext.active()); + // Same fallback as startLLMRequestSpan: prefer active OTel span for + // tools-inside-tools cases before falling back to the session root. + const ctx = resolveParentContext(parentCtx); const attributes: Attributes = { 'tool.name': toolName, @@ -409,9 +439,10 @@ export function startToolExecutionSpan(): Span { 'startToolExecutionSpan called outside runInToolSpanContext — span will not be parented to tool span', ); } - const ctx = parentCtx - ? trace.setSpan(otelContext.active(), parentCtx.span) - : (getSessionContext() ?? otelContext.active()); + // Without an explicit toolContext parent we still try the active OTel span + // (some tool execution paths run inside a withSpan() block from another + // subsystem) before falling back to the session root. + const ctx = resolveParentContext(parentCtx); const span = getTracer().startSpan( SPAN_TOOL_EXECUTION, @@ -437,6 +468,14 @@ export function endToolExecutionSpan( metadata?: { success?: boolean; error?: string; + /** + * Mark the execution as user-cancelled: success/error attributes are + * still recorded but status stays UNSET, mirroring setToolSpanCancelled + * on the parent tool span. Without this, success: false unconditionally + * sets ERROR and trace backends filtering for errors false-positive on + * user cancels (#4302 review). + */ + cancelled?: boolean; }, ): void { const spanId = getSpanId(span); @@ -459,8 +498,9 @@ export function endToolExecutionSpan( // No-metadata-no-status: matches endToolSpan. Callers that pre-set // status (e.g. via setToolSpanCancelled) and then call this without - // metadata get their pre-set status preserved. - if (metadata) { + // metadata get their pre-set status preserved. Cancellation also + // preserves UNSET so the child agrees with the cancelled parent. + if (metadata && !metadata.cancelled) { if (metadata.success !== false) { spanCtx.span.setStatus({ code: SpanStatusCode.OK }); } else { diff --git a/packages/core/src/telemetry/tracer.ts b/packages/core/src/telemetry/tracer.ts index 78cfa562c3d..ca524497d53 100644 --- a/packages/core/src/telemetry/tracer.ts +++ b/packages/core/src/telemetry/tracer.ts @@ -74,6 +74,10 @@ function safeEndSpan(span: Span): void { } } +// SYNC: keep parent-resolution logic in step with resolveParentContext() +// in telemetry/session-tracing.ts. Both helpers must use the same +// active-span-then-session-root precedence or trace trees become +// inconsistent between withSpan() spans and ALS-driven spans (#4302 review). function getParentContext(): Context { const active = context.active(); if (trace.getSpan(active)) {