fix(browser): Fix idle span ending

mydea · mydea · commit a4efccc1623c · 2024-05-31T11:13:17.000+02:00
diff --git a/packages/core/src/tracing/idleSpan.ts b/packages/core/src/tracing/idleSpan.ts
@@ -113,37 +113,48 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
   const previousActiveSpan = getActiveSpan();
   const span = _startIdleSpan(startSpanOptions);
 
-  function _endSpan(timestamp: number = timestampInSeconds()): void {
-    // Ensure we end with the last span timestamp, if possible
-    const spans = getSpanDescendants(span).filter(child => child !== span);
+  // We patch span.end to ensure we can run some things before the span is ended
+  // eslint-disable-next-line @typescript-eslint/unbound-method
+  span.end = new Proxy(span.end, {
+    apply(target, thisArg, args: Parameters<Span['end']>) {
+      if (beforeSpanEnd) {
+        beforeSpanEnd(span);
+      }
 
-    // If we have no spans, we just end, nothing else to do here
-    if (!spans.length) {
-      span.end(timestamp);
-      return;
-    }
+      const timestamp = args[0] || timestampInSeconds();
+      const spanEndTimestamp = spanTimeInputToSeconds(timestamp);
 
-    const childEndTimestamps = spans
-      .map(span => spanToJSON(span).timestamp)
-      .filter(timestamp => !!timestamp) as number[];
-    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
-    // 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);
-  }
+      // Ensure we end with the last span timestamp, if possible
+      const spans = getSpanDescendants(span).filter(child => child !== span);
+
+      // If we have no spans, we just end, nothing else to do here
+      if (!spans.length) {
+        onIdleSpanEnded(spanEndTimestamp);
+        return Reflect.apply(target, thisArg, args);
+      }
+
+      const childEndTimestamps = spans
+        .map(span => spanToJSON(span).timestamp)
+        .filter(timestamp => !!timestamp) as number[];
+      const latestSpanEndTimestamp = childEndTimestamps.length ? Math.max(...childEndTimestamps) : undefined;
+
+      // 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
+      // 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)),
+      );
+
+      onIdleSpanEnded(endTimestamp);
+      return Reflect.apply(target, thisArg, [endTimestamp]);
+    },
+  });
 
   /**
    * Cancels the existing idle timeout, if there is one.
@@ -173,7 +184,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     _idleTimeoutID = setTimeout(() => {
       if (!_finished && activities.size === 0 && _autoFinishAllowed) {
         _finishReason = FINISH_REASON_IDLE_TIMEOUT;
-        _endSpan(endTimestamp);
+        span.end(endTimestamp);
       }
     }, idleTimeout);
   }
@@ -186,7 +197,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     _idleTimeoutID = setTimeout(() => {
       if (!_finished && _autoFinishAllowed) {
         _finishReason = FINISH_REASON_HEARTBEAT_FAILED;
-        _endSpan(endTimestamp);
+        span.end(endTimestamp);
       }
     }, childSpanTimeout);
   }
@@ -223,21 +234,17 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     }
   }
 
-  function onIdleSpanEnded(): void {
+  function onIdleSpanEnded(endTimestamp: number): void {
     _finished = true;
     activities.clear();
 
-    if (beforeSpanEnd) {
-      beforeSpanEnd(span);
-    }
-
     _setSpanForScope(scope, previousActiveSpan);
 
     const spanJSON = spanToJSON(span);
 
-    const { timestamp: endTimestamp, start_timestamp: startTimestamp } = spanJSON;
+    const { start_timestamp: startTimestamp } = spanJSON;
     // This should never happen, but to make TS happy...
-    if (!endTimestamp || !startTimestamp) {
+    if (!startTimestamp) {
       return;
     }
 
@@ -267,7 +274,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
 
       // Add a delta with idle timeout so that we prevent false positives
       const timeoutWithMarginOfError = (finalTimeout + idleTimeout) / 1000;
-      const spanEndedBeforeFinalTimeout = childEndTimestamp - childStartTimestamp < timeoutWithMarginOfError;
+      const spanEndedBeforeFinalTimeout = childEndTimestamp - childStartTimestamp <= timeoutWithMarginOfError;
 
       if (DEBUG_BUILD) {
         const stringifiedSpan = JSON.stringify(childSpan, undefined, 2);
@@ -312,10 +319,6 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     }
 
     _popActivity(endedSpan.spanContext().spanId);
-
-    if (endedSpan === span) {
-      onIdleSpanEnded();
-    }
   });
 
   client.on('idleSpanEnableAutoFinish', spanToAllowAutoFinish => {
@@ -338,7 +341,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
     if (!_finished) {
       span.setStatus({ code: SPAN_STATUS_ERROR, message: 'deadline_exceeded' });
       _finishReason = FINISH_REASON_FINAL_TIMEOUT;
-      _endSpan();
+      span.end();
     }
   }, finalTimeout);
 
diff --git a/packages/core/src/tracing/sentrySpan.ts b/packages/core/src/tracing/sentrySpan.ts
@@ -342,7 +342,10 @@ export class SentrySpan implements Span {
 
     if (hasMeasurements) {
       DEBUG_BUILD &&
-        logger.log('[Measurements] Adding measurements to transaction', JSON.stringify(measurements, undefined, 2));
+        logger.log(
+          '[Measurements] Adding measurements to transaction event',
+          JSON.stringify(measurements, undefined, 2),
+        );
       transaction.measurements = measurements;
     }
 
diff --git a/packages/core/test/lib/tracing/idleSpan.test.ts b/packages/core/test/lib/tracing/idleSpan.test.ts
@@ -122,9 +122,9 @@ describe('startIdleSpan', () => {
       span.setAttribute('foo', 'bar');
       // Try adding a child here - we do this in browser tracing...
       const inner = startInactiveSpan({ name: 'from beforeSpanEnd', startTime: baseTimeInSeconds });
-      inner?.end(baseTimeInSeconds);
+      inner.end(baseTimeInSeconds + 1);
     });
-    const idleSpan = startIdleSpan({ name: 'idle span 2', startTime: baseTimeInSeconds }, { beforeSpanEnd });
+    const idleSpan = startIdleSpan({ name: 'idle span', startTime: baseTimeInSeconds }, { beforeSpanEnd });
     expect(idleSpan).toBeDefined();
 
     expect(beforeSpanEnd).not.toHaveBeenCalled();
@@ -141,6 +141,10 @@ describe('startIdleSpan', () => {
     expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
     const transaction = transactions[0];
 
+    expect(transaction.start_timestamp).toBe(baseTimeInSeconds);
+    // It considers the end time of the span we added in beforeSpanEnd
+    expect(transaction.timestamp).toBe(baseTimeInSeconds + 1);
+
     expect(transaction.contexts?.trace?.data).toEqual(
       expect.objectContaining({
         foo: 'bar',
@@ -178,9 +182,9 @@ describe('startIdleSpan', () => {
     });
 
     // discardedSpan - startTimestamp is too large
-    const discardedSpan = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 99 });
+    const discardedSpan = startInactiveSpan({ name: 'discarded span 1', startTime: baseTimeInSeconds + 99 });
     // discardedSpan2 - endTime is too large
-    const discardedSpan2 = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 3 });
+    const discardedSpan2 = startInactiveSpan({ name: 'discarded span 2', startTime: baseTimeInSeconds + 3 });
     discardedSpan2.end(baseTimeInSeconds + 99)!;
 
     // Should be cancelled - will not finish
