[No QA] Fix mixed clock domains in span duration logs

src/libs/telemetry/activeSpans.ts

@@ -2,7 +2,7 @@ import CONST from '@src/CONST';
 
 import type {Span, SpanAttributeValue, StartSpanOptions} from '@sentry/core';
 
-import {SPAN_STATUS_OK} from '@sentry/core';
+import {SPAN_STATUS_OK, spanTimeInputToSeconds} from '@sentry/core';
 import * as Sentry from '@sentry/react-native';
 import {AppState} from 'react-native';
 
@@ -13,6 +13,17 @@ type ActiveSpanEntry = {
 
 const activeSpans = new Map<string, ActiveSpanEntry>();
 
+function getPerformanceStartTimeForLog(startTime: StartSpanOptions['startTime']): number {
+    const performanceTimestamp = performance.now();
+    if (startTime === undefined) {
+        return performanceTimestamp;
+    }
+
+    // Sentry start times are Unix timestamps, while performance.now() is relative to the process start. Translate the timestamp once so elapsed time stays monotonic.
+    const epochStartTime = spanTimeInputToSeconds(startTime) * 1000;
+    return performanceTimestamp - (Date.now() - epochStartTime);
+}
+
 function startSpan(spanId: string, options: StartSpanOptions) {
     if ((AppState.currentState ?? CONST.APP_STATE.ACTIVE) !== CONST.APP_STATE.ACTIVE) {
         return;
@@ -26,12 +37,7 @@ function startSpan(spanId: string, options: StartSpanOptions) {
     });
     const span = Sentry.startInactiveSpan(options);
 
-    let startTimeForLog: number;
-    if (typeof options.startTime === 'number') {
-        startTimeForLog = options.startTime;
-    } else {
-        startTimeForLog = performance.now();
-    }
+    const startTimeForLog = getPerformanceStartTimeForLog(options.startTime);
 
     activeSpans.set(spanId, {span, startTimeForLog});
 
@@ -45,9 +51,9 @@ function endSpan(spanId: string) {
         return;
     }
     const {span, startTimeForLog} = entry;
-    const now = performance.now();
-    const durationMs = Math.round(now - startTimeForLog);
-    console.debug(`[Sentry][${spanId}] Ending span (${durationMs}ms)`, {spanId, durationMs, timestamp: now, attributes: Sentry.spanToJSON(span).data});
+    const performanceTimestamp = performance.now();
+    const durationMs = Math.round(performanceTimestamp - startTimeForLog);
+    console.debug(`[Sentry][${spanId}] Ending span (${durationMs}ms)`, {spanId, durationMs, timestamp: Date.now(), attributes: Sentry.spanToJSON(span).data});
     span.setStatus({code: SPAN_STATUS_OK});
 
     span.setAttribute(CONST.TELEMETRY.ATTRIBUTE_FINISHED_MANUALLY, true);

tests/unit/ActiveSpansTest.ts

@@ -0,0 +1,35 @@
+import {endSpan, startSpan} from '@libs/telemetry/activeSpans';
+
+import CONST from '@src/CONST';
+
+jest.mock('@sentry/react-native', () => ({
+    startInactiveSpan: () => ({
+        setAttribute: jest.fn(),
+        setStatus: jest.fn(),
+        end: jest.fn(),
+    }),
+    spanToJSON: () => ({data: {}}),
+}));
+
+afterEach(() => {
+    jest.restoreAllMocks();
+});
+
+describe('activeSpans', () => {
+    it('calculates the duration from an epoch start time using the monotonic clock', () => {
+        const dateNowSpy = jest.spyOn(Date, 'now').mockReturnValue(1_786_362_201_500);
+        const performanceNowSpy = jest.spyOn(performance, 'now').mockReturnValue(10_000);
+        const consoleDebugSpy = jest.spyOn(console, 'debug').mockImplementation(() => {});
+
+        startSpan(CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST, {
+            name: CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST,
+            startTime: 1_786_362_201_000,
+        });
+
+        dateNowSpy.mockReturnValue(1_786_362_201_750);
+        performanceNowSpy.mockReturnValue(10_250);
+        endSpan(CONST.TELEMETRY.SPAN_APP_STARTUP_NETWORK_REQUEST);
+
+        expect(consoleDebugSpy).toHaveBeenLastCalledWith(expect.stringContaining('Ending span (750ms)'), expect.objectContaining({durationMs: 750, timestamp: 1_786_362_201_750}));
+    });
+});