feat(browser): Improve idle span handling (#12065)

mydea · web-flow · commit ccb98ffc2722 · 2024-05-16T11:12:28.000+02:00
Closes #12051 This PR does two things: 1. Ensures we add helpful attributes to idle spans more consistently. We now add the `sentry.idle_span_finish_reason` attribute always for idle spans, not only when op == `ui.action.click`. This should also make it easier to debug stuff etc, and I see no reason to not always set this. Additionally, we also keep the number of spans we discarded (if any) for easier debugging too (as `sentry.idle_span_discarded_spans`). 2. We ensure that idle spans cannot exceed the configured `finalTimeout`. Previously, due to the order of things, it was possible that we ended a span very late, if it had a child span with a very late end timestamp (as we took the last child span timestamp). Possibly this could lead to overly long transactions. I think 2, combined with the fact that later we _do_ filter out child spans that ended after idle span, lead to the incorrect-length spans.
diff --git a/packages/core/src/tracing/idleSpan.ts b/packages/core/src/tracing/idleSpan.ts
@@ -129,15 +129,17 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     const latestSpanEndTimestamp = childEndTimestamps.length ? Math.max(...childEndTimestamps) : undefined;
 
     const spanEndTimestamp = spanTimeInputToSeconds(timestamp);
+    // In reality this should always exist here, but type-wise it may be undefined...
     const spanStartTimestamp = spanToJSON(span).start_timestamp;
 
     // The final endTimestamp should:
     // * Never be before the span start timestamp
     // * Be the latestSpanEndTimestamp, if there is one, and it is smaller than the passed span end timestamp
     // * Otherwise be the passed end timestamp
-    const endTimestamp = Math.max(
-      spanStartTimestamp || -Infinity,
-      Math.min(spanEndTimestamp, latestSpanEndTimestamp || Infinity),
+    // Final timestamp can never be after finalTimeout
+    const endTimestamp = Math.min(
+      spanStartTimestamp ? spanStartTimestamp + finalTimeout / 1000 : Infinity,
+      Math.max(spanStartTimestamp || -Infinity, Math.min(spanEndTimestamp, latestSpanEndTimestamp || Infinity)),
     );
 
     span.end(endTimestamp);
@@ -240,14 +242,15 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     }
 
     const attributes: SpanAttributes = spanJSON.data || {};
-    if (spanJSON.op === 'ui.action.click' && !attributes[SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON]) {
+    if (!attributes[SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON]) {
       span.setAttribute(SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON, _finishReason);
     }
 
     logger.log(`[Tracing] Idle span "${spanJSON.op}" finished`);
 
     const childSpans = getSpanDescendants(span).filter(child => child !== span);
 
+    let discardedSpans = 0;
     childSpans.forEach(childSpan => {
       // We cancel all pending spans with status "cancelled" to indicate the idle span was finished early
       if (childSpan.isRecording()) {
@@ -277,8 +280,13 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
 
       if (!spanEndedBeforeFinalTimeout || !spanStartedBeforeIdleSpanEnd) {
         removeChildSpanFromSpan(span, childSpan);
+        discardedSpans++;
       }
     });
+
+    if (discardedSpans > 0) {
+      span.setAttribute('sentry.idle_span_discarded_spans', discardedSpans);
+    }
   }
 
   client.on('spanStart', startedSpan => {
diff --git a/packages/core/test/lib/tracing/idleSpan.test.ts b/packages/core/test/lib/tracing/idleSpan.test.ts
@@ -230,6 +230,81 @@ describe('startIdleSpan', () => {
     );
   });
 
+  it('Ensures idle span cannot exceed finalTimeout', () => {
+    const transactions: Event[] = [];
+    const beforeSendTransaction = jest.fn(event => {
+      transactions.push(event);
+      return null;
+    });
+    const options = getDefaultTestClientOptions({
+      dsn,
+      tracesSampleRate: 1,
+      beforeSendTransaction,
+    });
+    const client = new TestClient(options);
+    setCurrentClient(client);
+    client.init();
+
+    // We want to accomodate a bit of drift there, so we ensure this starts earlier...
+    const finalTimeout = 99_999;
+    const baseTimeInSeconds = Math.floor(Date.now() / 1000) - 9999;
+
+    const idleSpan = startIdleSpan({ name: 'idle span', startTime: baseTimeInSeconds }, { finalTimeout: finalTimeout });
+    expect(idleSpan).toBeDefined();
+
+    // regular child - should be kept
+    const regularSpan = startInactiveSpan({
+      name: 'regular span',
+      startTime: baseTimeInSeconds + 2,
+    });
+    regularSpan.end(baseTimeInSeconds + 4);
+
+    // very late ending span
+    const discardedSpan = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 99 });
+    discardedSpan.end(baseTimeInSeconds + finalTimeout + 100);
+
+    // Should be cancelled - will not finish
+    const cancelledSpan = startInactiveSpan({
+      name: 'cancelled span',
+      startTime: baseTimeInSeconds + 4,
+    });
+
+    jest.runOnlyPendingTimers();
+
+    expect(regularSpan.isRecording()).toBe(false);
+    expect(idleSpan.isRecording()).toBe(false);
+    expect(discardedSpan.isRecording()).toBe(false);
+    expect(cancelledSpan.isRecording()).toBe(false);
+
+    expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
+    const transaction = transactions[0];
+
+    // End time is based on idle time etc.
+    const idleSpanEndTime = transaction.timestamp!;
+    expect(idleSpanEndTime).toEqual(baseTimeInSeconds + finalTimeout / 1000);
+
+    expect(transaction.spans).toHaveLength(2);
+    expect(transaction.spans).toEqual(
+      expect.arrayContaining([
+        expect.objectContaining({
+          description: 'regular span',
+          timestamp: baseTimeInSeconds + 4,
+          start_timestamp: baseTimeInSeconds + 2,
+        }),
+      ]),
+    );
+    expect(transaction.spans).toEqual(
+      expect.arrayContaining([
+        expect.objectContaining({
+          description: 'cancelled span',
+          timestamp: idleSpanEndTime,
+          start_timestamp: baseTimeInSeconds + 4,
+          status: 'cancelled',
+        }),
+      ]),
+    );
+  });
+
   it('emits span hooks', () => {
     const client = getClient()!;
 
@@ -274,6 +349,27 @@ describe('startIdleSpan', () => {
     expect(recordDroppedEventSpy).toHaveBeenCalledWith('sample_rate', 'transaction');
   });
 
+  it('sets finish reason when span is ended manually', () => {
+    let transaction: Event | undefined;
+    const beforeSendTransaction = jest.fn(event => {
+      transaction = event;
+      return null;
+    });
+    const options = getDefaultTestClientOptions({ dsn, tracesSampleRate: 1, beforeSendTransaction });
+    const client = new TestClient(options);
+    setCurrentClient(client);
+    client.init();
+
+    const span = startIdleSpan({ name: 'foo' });
+    span.end();
+    jest.runOnlyPendingTimers();
+
+    expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
+    expect(transaction?.contexts?.trace?.data?.[SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON]).toEqual(
+      'externalFinish',
+    );
+  });
+
   it('sets finish reason when span ends', () => {
     let transaction: Event | undefined;
     const beforeSendTransaction = jest.fn(event => {
@@ -285,8 +381,7 @@ describe('startIdleSpan', () => {
     setCurrentClient(client);
     client.init();
 
-    // This is only set when op === 'ui.action.click'
-    startIdleSpan({ name: 'foo', op: 'ui.action.click' });
+    startIdleSpan({ name: 'foo' });
     startSpan({ name: 'inner' }, () => {});
     jest.runOnlyPendingTimers();
 
@@ -296,6 +391,57 @@ describe('startIdleSpan', () => {
     );
   });
 
+  it('sets finish reason when span ends via expired heartbeat timeout', () => {
+    let transaction: Event | undefined;
+    const beforeSendTransaction = jest.fn(event => {
+      transaction = event;
+      return null;
+    });
+    const options = getDefaultTestClientOptions({ dsn, tracesSampleRate: 1, beforeSendTransaction });
+    const client = new TestClient(options);
+    setCurrentClient(client);
+    client.init();
+
+    startIdleSpan({ name: 'foo' });
+    startSpanManual({ name: 'inner' }, () => {});
+    jest.runOnlyPendingTimers();
+
+    expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
+    expect(transaction?.contexts?.trace?.data?.[SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON]).toEqual(
+      'heartbeatFailed',
+    );
+  });
+
+  it('sets finish reason when span ends via final timeout', () => {
+    let transaction: Event | undefined;
+    const beforeSendTransaction = jest.fn(event => {
+      transaction = event;
+      return null;
+    });
+    const options = getDefaultTestClientOptions({ dsn, tracesSampleRate: 1, beforeSendTransaction });
+    const client = new TestClient(options);
+    setCurrentClient(client);
+    client.init();
+
+    startIdleSpan({ name: 'foo' }, { finalTimeout: TRACING_DEFAULTS.childSpanTimeout * 2 });
+
+    const span1 = startInactiveSpan({ name: 'inner' });
+    jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1);
+    span1.end();
+
+    const span2 = startInactiveSpan({ name: 'inner2' });
+    jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1);
+    span2.end();
+
+    startInactiveSpan({ name: 'inner3' });
+    jest.runOnlyPendingTimers();
+
+    expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
+    expect(transaction?.contexts?.trace?.data?.[SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON]).toEqual(
+      'finalTimeout',
+    );
+  });
+
   it('uses finish reason set outside when span ends', () => {
     let transaction: Event | undefined;
     const beforeSendTransaction = jest.fn(event => {
@@ -307,8 +453,7 @@ describe('startIdleSpan', () => {
     setCurrentClient(client);
     client.init();
 
-    // This is only set when op === 'ui.action.click'
-    const span = startIdleSpan({ name: 'foo', op: 'ui.action.click' });
+    const span = startIdleSpan({ name: 'foo' });
     span.setAttribute(SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON, 'custom reason');
     startSpan({ name: 'inner' }, () => {});
     jest.runOnlyPendingTimers();
@@ -496,7 +641,7 @@ describe('startIdleSpan', () => {
 
   describe('trim end timestamp', () => {
     it('trims end to highest child span end', () => {
-      const idleSpan = startIdleSpan({ name: 'foo', startTime: 1000 });
+      const idleSpan = startIdleSpan({ name: 'foo', startTime: 1000 }, { finalTimeout: 99_999_999 });
       expect(idleSpan).toBeDefined();
 
       const span1 = startInactiveSpan({ name: 'span1', startTime: 1001 });
@@ -515,8 +660,28 @@ describe('startIdleSpan', () => {
       expect(spanToJSON(idleSpan!).timestamp).toBe(1100);
     });
 
+    it('trims end to final timeout', () => {
+      const idleSpan = startIdleSpan({ name: 'foo', startTime: 1000 }, { finalTimeout: 30_000 });
+      expect(idleSpan).toBeDefined();
+
+      const span1 = startInactiveSpan({ name: 'span1', startTime: 1001 });
+      span1?.end(1005);
+
+      const span2 = startInactiveSpan({ name: 'span2', startTime: 1002 });
+      span2?.end(1100);
+
+      const span3 = startInactiveSpan({ name: 'span1', startTime: 1050 });
+      span3?.end(1060);
+
+      expect(getActiveSpan()).toBe(idleSpan);
+
+      jest.runAllTimers();
+
+      expect(spanToJSON(idleSpan!).timestamp).toBe(1030);
+    });
+
     it('keeps lower span endTime than highest child span end', () => {
-      const idleSpan = startIdleSpan({ name: 'foo', startTime: 1000 });
+      const idleSpan = startIdleSpan({ name: 'foo', startTime: 1000 }, { finalTimeout: 99_999_999 });
       expect(idleSpan).toBeDefined();
 
       const span1 = startInactiveSpan({ name: 'span1', startTime: 999_999_999 });
