fix(telemetry): Phase 1.5 polish — fallback order, abort-as-result, log/span consistency

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<typeof createMockToolSpan>,
-      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();
   });
 });
 

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) {

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<typeof setTimeout>;
+    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<typeof setTimeout>;
+      }
+      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<void>((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<typeof vi.fn> };
+
+      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<typeof setTimeout>;
+    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<typeof setTimeout>;
+      }
+      return realSetTimeout(...args);
+    }) as typeof setTimeout);
+
+    try {
+      let releaseStream: (() => void) | undefined;
+      const gate = new Promise<void>((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<typeof vi.fn> };
+
+      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' },