fix(browser): Apply Http timing attributes to streamed http.client spans (#19643)

This PR fixes a temporary bug in span streaming where we didn't add Http
timing attributes (see
#19613). We can fix
this by following OTels approach:

- delay the ending of `http.client` spans until either 300ms pass by or
we receive the PerformanceResourceTiming entry with the respective
timing information. Of course we end the span with the original
timestamp then.
- Unfortunately, we can only do this for streamed span because
transaction-based spans cannot stay open longer than their parent (e.g.
a pageload or navigation). Otherwise they'd get dropped. So we have to
differentiate between the two modes here (RIP bundle size 😢)
- To ensure we don't flush unnecessarily often, we also now delay
flushing the span buffer for 500ms after a segment span ends. This
slightly changed test semantics in a few integration tests because
manually consecutively segments are now also sent in one envelope. This
is completely fine (actually preferred) because we flush less often
(i.e. fewer requests).

closes #19613

Author: Lms24

.size-limit.js

@@ -241,7 +241,7 @@ module.exports = [
     path: createCDNPath('bundle.tracing.min.js'),
     gzip: false,
     brotli: false,
-    limit: '129 KB',
+    limit: '130 KB',
   },
   {
     name: 'CDN Bundle (incl. Logs, Metrics) - uncompressed',

dev-packages/browser-integration-tests/suites/tracing/browserTracingIntegration/http-timings-streamed/test.ts

@@ -3,16 +3,8 @@ import { sentryTest } from '../../../../utils/fixtures';
 import { shouldSkipTracingTest, testingCdnBundle } from '../../../../utils/helpers';
 import { getSpanOp, waitForStreamedSpans } from '../../../../utils/spanUtils';
 
-/**
- * This test details a limitation of span streaming in comparison to transaction-based tracing:
- * We can no longer attach http PerformanceResourceTiming attributes to http.client spans in
- * span streaming mode. The reason is that we track `http.client` spans in real time but only
- * get the detailed timing information after the span already ended.
- * We can probably fix this (somehat at least) but will do so in a follow-up PR.
- * @see https://github.com/getsentry/sentry-javascript/issues/19613
- */
 sentryTest(
-  "[limitation] doesn't add http timing to http.client spans in span streaming mode",
+  'adds http timing to http.client spans in span streaming mode',
   async ({ browserName, getLocalTestUrl, page }) => {
     const supportedBrowsers = ['chromium', 'firefox'];
 
@@ -49,7 +41,7 @@ sentryTest(
         end_timestamp: expect.any(Number),
         trace_id: pageloadSpan?.trace_id,
         status: 'ok',
-        attributes: expect.not.objectContaining({
+        attributes: expect.objectContaining({
           'http.request.redirect_start': expect.any(Object),
           'http.request.redirect_end': expect.any(Object),
           'http.request.worker_start': expect.any(Object),

dev-packages/browser-integration-tests/suites/tracing/setSpanActive-streamed/nested-parentAlwaysRoot/test.ts

@@ -11,27 +11,22 @@ sentryTest(
     const checkoutSpansPromise = waitForStreamedSpans(page, spans =>
       spans.some(s => s.name === 'checkout-flow' && s.is_segment),
     );
-    const postCheckoutSpansPromise = waitForStreamedSpans(page, spans =>
-      spans.some(s => s.name === 'post-checkout' && s.is_segment),
-    );
 
     const url = await getLocalTestUrl({ testDir: __dirname });
     await page.goto(url);
 
     const checkoutSpans = await checkoutSpansPromise;
-    const postCheckoutSpans = await postCheckoutSpansPromise;
 
     const checkoutSpan = checkoutSpans.find(s => s.name === 'checkout-flow');
-    const postCheckoutSpan = postCheckoutSpans.find(s => s.name === 'post-checkout');
+    const postCheckoutSpan = checkoutSpans.find(s => s.name === 'post-checkout');
 
     const checkoutSpanId = checkoutSpan?.span_id;
     const postCheckoutSpanId = postCheckoutSpan?.span_id;
 
     expect(checkoutSpanId).toMatch(/[a-f\d]{16}/);
     expect(postCheckoutSpanId).toMatch(/[a-f\d]{16}/);
 
-    expect(checkoutSpans.filter(s => !s.is_segment)).toHaveLength(4);
-    expect(postCheckoutSpans.filter(s => !s.is_segment)).toHaveLength(1);
+    expect(checkoutSpans.filter(s => !s.is_segment)).toHaveLength(5);
 
     const checkoutStep1 = checkoutSpans.find(s => s.name === 'checkout-step-1');
     const checkoutStep2 = checkoutSpans.find(s => s.name === 'checkout-step-2');
@@ -56,7 +51,7 @@ sentryTest(
 
     // post-checkout trace is started as a new trace because ending checkoutSpan removes the active
     // span on the scope
-    const postCheckoutStep1 = postCheckoutSpans.find(s => s.name === 'post-checkout-1');
+    const postCheckoutStep1 = checkoutSpans.find(s => s.name === 'post-checkout-1');
     expect(postCheckoutStep1).toBeDefined();
     expect(postCheckoutStep1?.parent_span_id).toBe(postCheckoutSpanId);
   },

dev-packages/browser-integration-tests/suites/tracing/setSpanActive-streamed/nested/test.ts

@@ -11,27 +11,22 @@ sentryTest(
     const checkoutSpansPromise = waitForStreamedSpans(page, spans =>
       spans.some(s => s.name === 'checkout-flow' && s.is_segment),
     );
-    const postCheckoutSpansPromise = waitForStreamedSpans(page, spans =>
-      spans.some(s => s.name === 'post-checkout' && s.is_segment),
-    );
 
     const url = await getLocalTestUrl({ testDir: __dirname });
     await page.goto(url);
 
     const checkoutSpans = await checkoutSpansPromise;
-    const postCheckoutSpans = await postCheckoutSpansPromise;
 
     const checkoutSpan = checkoutSpans.find(s => s.name === 'checkout-flow');
-    const postCheckoutSpan = postCheckoutSpans.find(s => s.name === 'post-checkout');
+    const postCheckoutSpan = checkoutSpans.find(s => s.name === 'post-checkout');
 
     const checkoutSpanId = checkoutSpan?.span_id;
     const postCheckoutSpanId = postCheckoutSpan?.span_id;
 
     expect(checkoutSpanId).toMatch(/[a-f\d]{16}/);
     expect(postCheckoutSpanId).toMatch(/[a-f\d]{16}/);
 
-    expect(checkoutSpans.filter(s => !s.is_segment)).toHaveLength(4);
-    expect(postCheckoutSpans.filter(s => !s.is_segment)).toHaveLength(1);
+    expect(checkoutSpans.filter(s => !s.is_segment)).toHaveLength(5);
 
     const checkoutStep1 = checkoutSpans.find(s => s.name === 'checkout-step-1');
     const checkoutStep2 = checkoutSpans.find(s => s.name === 'checkout-step-2');
@@ -51,7 +46,7 @@ sentryTest(
     // root span due to this being default behaviour in browser environments
     expect(checkoutStep21?.parent_span_id).toBe(checkoutSpanId);
 
-    const postCheckoutStep1 = postCheckoutSpans.find(s => s.name === 'post-checkout-1');
+    const postCheckoutStep1 = checkoutSpans.find(s => s.name === 'post-checkout-1');
     expect(postCheckoutStep1).toBeDefined();
     expect(postCheckoutStep1?.parent_span_id).toBe(postCheckoutSpanId);
   },

packages/browser/src/integrations/spanstreaming.ts

@@ -58,7 +58,12 @@ export const spanStreamingIntegration = defineIntegration(() => {
       // In addition to capturing the span, we also flush the trace when the segment
       // span ends to ensure things are sent timely. We never know when the browser
       // is closed, users navigate away, etc.
-      client.on('afterSegmentSpanEnd', segmentSpan => buffer.flush(segmentSpan.spanContext().traceId));
+      client.on('afterSegmentSpanEnd', segmentSpan => {
+        const traceId = segmentSpan.spanContext().traceId;
+        setTimeout(() => {
+          buffer.flush(traceId);
+        }, 500);
+      });
     },
   };
 }) satisfies IntegrationFn;

packages/browser/src/tracing/request.ts

@@ -1,10 +1,12 @@
+/* eslint-disable max-lines */
 import type {
   Client,
   HandlerDataXhr,
   RequestHookInfo,
   ResponseHookInfo,
   SentryWrappedXMLHttpRequest,
   Span,
+  SpanTimeInput,
 } from '@sentry/core';
 import {
   addFetchEndInstrumentationHandler,
@@ -14,6 +16,7 @@ import {
   getLocationHref,
   getTraceData,
   hasSpansEnabled,
+  hasSpanStreamingEnabled,
   instrumentFetchRequest,
   parseUrl,
   SEMANTIC_ATTRIBUTE_SENTRY_OP,
@@ -25,6 +28,7 @@ import {
   stringMatchesSomePattern,
   stripDataUrlContent,
   stripUrlQueryAndFragment,
+  timestampInSeconds,
 } from '@sentry/core';
 import type { XhrHint } from '@sentry-internal/browser-utils';
 import {
@@ -205,7 +209,7 @@ export function instrumentOutgoingRequests(client: Client, _options?: Partial<Re
         });
 
         if (enableHTTPTimings) {
-          addHTTPTimings(createdSpan);
+          addHTTPTimings(createdSpan, client);
         }
 
         onRequestSpanStart?.(createdSpan, { headers: handlerData.headers });
@@ -226,7 +230,7 @@ export function instrumentOutgoingRequests(client: Client, _options?: Partial<Re
 
       if (createdSpan) {
         if (enableHTTPTimings) {
-          addHTTPTimings(createdSpan);
+          addHTTPTimings(createdSpan, client);
         }
 
         onRequestSpanStart?.(createdSpan, {
@@ -237,26 +241,64 @@ export function instrumentOutgoingRequests(client: Client, _options?: Partial<Re
   }
 }
 
+/**
+ * The maximum time (ms) to wait for PerformanceResourceTiming data before ending the span.
+ * Same approach is used by OTel's browser fetch instrumentation:
+ * See {@link https://github.com/open-telemetry/opentelemetry-js/blob/30f94fe99339287b1e4d3c8bb90172c2523f06f4/experimental/packages/opentelemetry-instrumentation-fetch/src/fetch.ts#L352-L372}
+ */
+const HTTP_TIMING_WAIT_MS = 300;
+
 /**
  * Creates a temporary observer to listen to the next fetch/xhr resourcing timings,
  * so that when timings hit their per-browser limit they don't need to be removed.
  *
  * @param span A span that has yet to be finished, must contain `url` on data.
  */
-function addHTTPTimings(span: Span): void {
+function addHTTPTimings(span: Span, client: Client): void {
   const { url } = spanToJSON(span).data;
 
   if (!url || typeof url !== 'string') {
     return;
   }
 
-  const cleanup = addPerformanceInstrumentationHandler('resource', ({ entries }) => {
+  // Clean up the performance observer and other resources
+  // We have to wait here because otherwise this cleans itself up before it is fully done.
+  // Default (non-streaming): just deregister the observer.
+  let onEntryFound = (): void => void setTimeout(unsubscribePerformanceObsever);
+
+  // For streamed spans, we have to artificially delay the ending of the span until we
+  // either receive the timing data, or HTTP_TIMING_WAIT_MS elapses.
+  if (hasSpanStreamingEnabled(client)) {
+    const originalEnd = span.end.bind(span);
+
+    span.end = (endTimestamp?: SpanTimeInput) => {
+      const capturedEndTimestamp = endTimestamp ?? timestampInSeconds();
+      let isEnded = false;
+
+      const endSpanAndCleanup = (): void => {
+        if (isEnded) {
+          return;
+        }
+        isEnded = true;
+        setTimeout(unsubscribePerformanceObsever);
+        originalEnd(capturedEndTimestamp);
+        clearTimeout(fallbackTimeout);
+      };
+
+      onEntryFound = endSpanAndCleanup;
+
+      // Fallback: always end the span after HTTP_TIMING_WAIT_MS even if no
+      // PerformanceResourceTiming entry arrives (e.g. cross-origin without
+      // Timing-Allow-Origin, or the browser didn't fire the observer in time).
+      const fallbackTimeout = setTimeout(endSpanAndCleanup, HTTP_TIMING_WAIT_MS);
+    };
+  }
+
+  const unsubscribePerformanceObsever = addPerformanceInstrumentationHandler('resource', ({ entries }) => {
     entries.forEach(entry => {
       if (isPerformanceResourceTiming(entry) && entry.name.endsWith(url)) {
         span.setAttributes(resourceTimingToSpanAttributes(entry));
-        // In the next tick, clean this handler up
-        // We have to wait here because otherwise this cleans itself up before it is fully done
-        setTimeout(cleanup);
+        onEntryFound();
       }
     });
   });

packages/browser/test/integrations/spanstreaming.test.ts

@@ -171,7 +171,8 @@ describe('spanStreamingIntegration', () => {
     expect(mockSpanBufferInstance.flush).not.toHaveBeenCalled();
   });
 
-  it('flushes the trace when the segment span ends', () => {
+  it('flushes the trace when the segment span ends after a delay for close to finished child spans', () => {
+    vi.useFakeTimers();
     const client = new BrowserClient({
       ...getDefaultBrowserClientOptions(),
       dsn: 'https://username@domain/123',
@@ -185,6 +186,10 @@ describe('spanStreamingIntegration', () => {
     const span = new SentryCore.SentrySpan({ name: 'test' });
     client.emit('afterSegmentSpanEnd', span);
 
+    vi.advanceTimersByTime(500);
+
     expect(mockSpanBufferInstance.flush).toHaveBeenCalledWith(span.spanContext().traceId);
+
+    vi.useRealTimers();
   });
 });