fix(otel): Don't ignore child spans after the root is sent (#16416)

This fixes a critical issue I was having with Mastra where almost all my
spans from a workflow run were getting stuck due to their parent span
being sent almost immediately. I'm guessing this has to do something
with `async` stuff going on. Regardless, by treating these children as
'root spans' I was able to get them out and displayed correctly in
Spotlight.

What this does is creates a 5-min capped 'already sent span ids' cache
and treats any span that has a parent id in this list as a root span to
get them unstuck.


![image](https://github.com/user-attachments/assets/bae9376b-d6db-4c87-ae0f-9f30021f3a8d)

---------

Co-authored-by: Charly Gomez <charly.gomez@sentry.io>

Author: BYK

dev-packages/e2e-tests/test-applications/nextjs-14/playwright.config.ts

@@ -5,15 +5,9 @@ if (!testEnv) {
   throw new Error('No test env defined');
 }
 
-const config = getPlaywrightConfig(
-  {
-    startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030',
-    port: 3030,
-  },
-  {
-    // This comes with the risk of tests leaking into each other but the tests run quite slow so we should parallelize
-    workers: '100%',
-  },
-);
+const config = getPlaywrightConfig({
+  startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030',
+  port: 3030,
+});
 
 export default config;

dev-packages/e2e-tests/test-applications/nextjs-app-dir/playwright.config.mjs

@@ -5,15 +5,9 @@ if (!testEnv) {
   throw new Error('No test env defined');
 }
 
-const config = getPlaywrightConfig(
-  {
-    startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030',
-    port: 3030,
-  },
-  {
-    // This comes with the risk of tests leaking into each other but the tests run quite slow so we should parallelize
-    workers: '100%',
-  },
-);
+const config = getPlaywrightConfig({
+  startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030',
+  port: 3030,
+});
 
 export default config;

dev-packages/opentelemetry-v2-tests/test/integration/transactions.test.ts

@@ -1,7 +1,6 @@
 import type { SpanContext } from '@opentelemetry/api';
 import { context, ROOT_CONTEXT, trace, TraceFlags } from '@opentelemetry/api';
 import { TraceState } from '@opentelemetry/core';
-import type { SpanProcessor } from '@opentelemetry/sdk-trace-base';
 import type { Event, TransactionEvent } from '@sentry/core';
 import {
   addBreadcrumb,
@@ -15,7 +14,6 @@ import {
 } from '@sentry/core';
 import { afterEach, describe, expect, it, vi } from 'vitest';
 import { SENTRY_TRACE_STATE_DSC } from '../../../../packages/opentelemetry/src/constants';
-import { SentrySpanProcessor } from '../../../../packages/opentelemetry/src/spanProcessor';
 import { startInactiveSpan, startSpan } from '../../../../packages/opentelemetry/src/trace';
 import { makeTraceState } from '../../../../packages/opentelemetry/src/utils/makeTraceState';
 import { cleanupOtel, getProvider, getSpanProcessor, mockSdkInit } from '../helpers/mockSdkInit';
@@ -550,7 +548,60 @@ describe('Integration | Transactions', () => {
     expect(finishedSpans.length).toBe(0);
   });
 
-  it('discards child spans that are finished after their parent span', async () => {
+it('collects child spans that are finished within 5 minutes their parent span has been sent', async () => {
+  const timeout = 5 * 60 * 1000;
+  const now = Date.now();
+  vi.useFakeTimers();
+  vi.setSystemTime(now);
+
+  const logs: unknown[] = [];
+  vi.spyOn(logger, 'log').mockImplementation(msg => logs.push(msg));
+
+  const transactions: Event[] = [];
+
+  mockSdkInit({
+    tracesSampleRate: 1,
+    beforeSendTransaction: event => {
+      transactions.push(event);
+      return null;
+    },
+  });
+
+  const provider = getProvider();
+  const spanProcessor = getSpanProcessor();
+
+  const exporter = spanProcessor ? spanProcessor['_exporter'] : undefined;
+
+  if (!exporter) {
+    throw new Error('No exporter found, aborting test...');
+  }
+
+  startSpanManual({ name: 'test name' }, async span => {
+    const subSpan = startInactiveSpan({ name: 'inner span 1' });
+    subSpan.end();
+
+    const subSpan2 = startInactiveSpan({ name: 'inner span 2' });
+
+    span.end();
+
+    setTimeout(() => {
+      subSpan2.end();
+    }, timeout - 2);
+  });
+
+  vi.advanceTimersByTime(timeout - 1);
+
+  expect(transactions).toHaveLength(2);
+  expect(transactions[0]?.spans).toHaveLength(1);
+
+  const finishedSpans: any = exporter['_finishedSpanBuckets'].flatMap(bucket =>
+    bucket ? Array.from(bucket.spans) : [],
+  );
+  expect(finishedSpans.length).toBe(0);
+});
+
+  it('discards child spans that are finished after 5 minutes their parent span has been sent', async () => {
+    const timeout = 5 * 60 * 1000;
     const now = Date.now();
     vi.useFakeTimers();
     vi.setSystemTime(now);
@@ -587,10 +638,10 @@ describe('Integration | Transactions', () => {
 
       setTimeout(() => {
         subSpan2.end();
-      }, 1);
+      }, timeout + 1);
     });
 
-    vi.advanceTimersByTime(2);
+    vi.advanceTimersByTime(timeout + 2);
 
     expect(transactions).toHaveLength(1);
     expect(transactions[0]?.spans).toHaveLength(1);

packages/opentelemetry/src/spanExporter.ts

@@ -71,6 +71,9 @@ export class SentrySpanExporter {
   private _finishedSpanBucketSize: number;
   private _spansToBucketEntry: WeakMap<ReadableSpan, FinishedSpanBucket>;
   private _lastCleanupTimestampInS: number;
+  // Essentially a a set of span ids that are already sent. The values are expiration
+  // times in this cache so we don't hold onto them indefinitely.
+  private _sentSpans: Map<string, number>;
 
   public constructor(options?: {
     /** Lower bound of time in seconds until spans that are buffered but have not been sent as part of a transaction get cleared from memory. */
@@ -80,6 +83,48 @@ export class SentrySpanExporter {
     this._finishedSpanBuckets = new Array(this._finishedSpanBucketSize).fill(undefined);
     this._lastCleanupTimestampInS = Math.floor(Date.now() / 1000);
     this._spansToBucketEntry = new WeakMap();
+    this._sentSpans = new Map<string, number>();
+  }
+
+  /**
+   * Check if a span with the given ID has already been sent using the `_sentSpans` as a cache.
+   * Purges "expired" spans from the cache upon checking.
+   * @param spanId The span id to check.
+   * @returns Whether the span is already sent in the past X seconds.
+   */
+  public isSpanAlreadySent(spanId: string): boolean {
+    const expirationTime = this._sentSpans.get(spanId);
+    if (expirationTime) {
+      if (Date.now() >= expirationTime) {
+        this._sentSpans.delete(spanId); // Remove expired span
+      } else {
+        return true;
+      }
+    }
+    return false;
+  }
+
+  /** Remove "expired" span id entries from the _sentSpans cache. */
+  public flushSentSpanCache(): void {
+    const currentTimestamp = Date.now();
+    // Note, it is safe to delete items from the map as we go: https://stackoverflow.com/a/35943995/90297
+    for (const [spanId, expirationTime] of this._sentSpans.entries()) {
+      if (expirationTime <= currentTimestamp) {
+        this._sentSpans.delete(spanId);
+      }
+    }
+  }
+
+  /** Check if a node is a completed root node or a node whose parent has already been sent */
+  public nodeIsCompletedRootNode(node: SpanNode): node is SpanNodeCompleted {
+    return !!node.span && (!node.parentNode || this.isSpanAlreadySent(node.parentNode.id));
+  }
+
+  /** Get all completed root nodes from a list of nodes */
+  public getCompletedRootNodes(nodes: SpanNode[]): SpanNodeCompleted[] {
+    // TODO: We should be able to remove the explicit `node is SpanNodeCompleted` type guard
+    //       once we stop supporting TS < 5.5
+    return nodes.filter((node): node is SpanNodeCompleted => this.nodeIsCompletedRootNode(node));
   }
 
   /** Export a single span. */
@@ -113,7 +158,8 @@ export class SentrySpanExporter {
     this._spansToBucketEntry.set(span, currentBucket);
 
     // If the span doesn't have a local parent ID (it's a root span), we're gonna flush all the ended spans
-    if (!getLocalParentId(span)) {
+    const localParentId = getLocalParentId(span);
+    if (!localParentId || this.isSpanAlreadySent(localParentId)) {
       this._clearTimeout();
 
       // If we got a parent span, we try to send the span tree
@@ -128,30 +174,29 @@ export class SentrySpanExporter {
   public flush(): void {
     this._clearTimeout();
 
-    const finishedSpans: ReadableSpan[] = [];
-    this._finishedSpanBuckets.forEach(bucket => {
-      if (bucket) {
-        finishedSpans.push(...bucket.spans);
-      }
-    });
+    const finishedSpans: ReadableSpan[] = this._finishedSpanBuckets.flatMap(bucket =>
+      bucket ? Array.from(bucket.spans) : [],
+    );
 
-    const sentSpans = maybeSend(finishedSpans);
+    this.flushSentSpanCache();
+    const sentSpans = this._maybeSend(finishedSpans);
+    for (const span of finishedSpans) {
+      this._sentSpans.set(span.spanContext().spanId, Date.now() + DEFAULT_TIMEOUT * 1000);
+    }
 
     const sentSpanCount = sentSpans.size;
-
     const remainingOpenSpanCount = finishedSpans.length - sentSpanCount;
-
     DEBUG_BUILD &&
       logger.log(
         `SpanExporter exported ${sentSpanCount} spans, ${remainingOpenSpanCount} spans are waiting for their parent spans to finish`,
       );
 
-    sentSpans.forEach(span => {
+    for (const span of sentSpans) {
       const bucketEntry = this._spansToBucketEntry.get(span);
       if (bucketEntry) {
         bucketEntry.spans.delete(span);
       }
-    });
+    }
   }
 
   /** Clear the exporter. */
@@ -167,59 +212,51 @@ export class SentrySpanExporter {
       this._flushTimeout = undefined;
     }
   }
-}
-
-/**
- * Send the given spans, but only if they are part of a finished transaction.
- *
- * Returns the sent spans.
- * Spans remain unsent when their parent span is not yet finished.
- * This will happen regularly, as child spans are generally finished before their parents.
- * But it _could_ also happen because, for whatever reason, a parent span was lost.
- * In this case, we'll eventually need to clean this up.
- */
-function maybeSend(spans: ReadableSpan[]): Set<ReadableSpan> {
-  const grouped = groupSpansWithParents(spans);
-  const sentSpans = new Set<ReadableSpan>();
 
-  const rootNodes = getCompletedRootNodes(grouped);
+  /**
+   * Send the given spans, but only if they are part of a finished transaction.
+   *
+   * Returns the sent spans.
+   * Spans remain unsent when their parent span is not yet finished.
+   * This will happen regularly, as child spans are generally finished before their parents.
+   * But it _could_ also happen because, for whatever reason, a parent span was lost.
+   * In this case, we'll eventually need to clean this up.
+   */
+  private _maybeSend(spans: ReadableSpan[]): Set<ReadableSpan> {
+    const grouped = groupSpansWithParents(spans);
+    const sentSpans = new Set<ReadableSpan>();
 
-  rootNodes.forEach(root => {
-    const span = root.span;
-    sentSpans.add(span);
-    const transactionEvent = createTransactionForOtelSpan(span);
+    const rootNodes = this.getCompletedRootNodes(grouped);
 
-    // We'll recursively add all the child spans to this array
-    const spans = transactionEvent.spans || [];
+    for (const root of rootNodes) {
+      const span = root.span;
+      sentSpans.add(span);
+      const transactionEvent = createTransactionForOtelSpan(span);
 
-    root.children.forEach(child => {
-      createAndFinishSpanForOtelSpan(child, spans, sentSpans);
-    });
+      // We'll recursively add all the child spans to this array
+      const spans = transactionEvent.spans || [];
 
-    // spans.sort() mutates the array, but we do not use this anymore after this point
-    // so we can safely mutate it here
-    transactionEvent.spans =
-      spans.length > MAX_SPAN_COUNT
-        ? spans.sort((a, b) => a.start_timestamp - b.start_timestamp).slice(0, MAX_SPAN_COUNT)
-        : spans;
+      for (const child of root.children) {
+        createAndFinishSpanForOtelSpan(child, spans, sentSpans);
+      }
 
-    const measurements = timedEventsToMeasurements(span.events);
-    if (measurements) {
-      transactionEvent.measurements = measurements;
-    }
+      // spans.sort() mutates the array, but we do not use this anymore after this point
+      // so we can safely mutate it here
+      transactionEvent.spans =
+        spans.length > MAX_SPAN_COUNT
+          ? spans.sort((a, b) => a.start_timestamp - b.start_timestamp).slice(0, MAX_SPAN_COUNT)
+          : spans;
 
-    captureEvent(transactionEvent);
-  });
-
-  return sentSpans;
-}
+      const measurements = timedEventsToMeasurements(span.events);
+      if (measurements) {
+        transactionEvent.measurements = measurements;
+      }
 
-function nodeIsCompletedRootNode(node: SpanNode): node is SpanNodeCompleted {
-  return !!node.span && !node.parentNode;
-}
+      captureEvent(transactionEvent);
+    }
 
-function getCompletedRootNodes(nodes: SpanNode[]): SpanNodeCompleted[] {
-  return nodes.filter(nodeIsCompletedRootNode);
+    return sentSpans;
+  }
 }
 
 function parseSpan(span: ReadableSpan): { op?: string; origin?: SpanOrigin; source?: TransactionSource } {