[No QA] Add flash, capture method and time since app start to the shutter-to-confirmation span

src/CONST/index.ts

@@ -2919,6 +2919,7 @@ const CONST = {
         ATTRIBUTE_NEUTRAL_ZOOM: 'neutral_zoom',
         ATTRIBUTE_ODOMETER_IMAGE_TYPE: 'odometer_image_type',
         ATTRIBUTE_DURATION_SINCE_NATIVE_APP_STARTUP_MS: 'duration_since_native_app_startup_ms',
+        ATTRIBUTE_DURATION_SINCE_JS_STARTUP_MS: 'duration_since_js_startup_ms',
         CAPTURE_METHOD: {
             PHOTO: 'photo',
             SNAPSHOT: 'snapshot',

src/libs/telemetry/nativeAppStartTime.ts

@@ -0,0 +1,34 @@
+// Elapsed time takes the larger of the Date.now() and performance.now() deltas: Date.now() goes backwards when the
+// device clock is corrected, and performance.now() stops during Android deep sleep. JS cannot tell a forward clock
+// correction from sleep, so a forward correction after setup inflates the value.
+let appStartAgeAtSetupMs: number | undefined;
+let dateNowAtSetupMs: number | undefined;
+let performanceNowAtSetupMs = 0;
+
+function setNativeAppStartTime(timestampMs: number | undefined) {
+    dateNowAtSetupMs = Date.now();
+    performanceNowAtSetupMs = performance.now();
+    appStartAgeAtSetupMs = timestampMs === undefined ? undefined : dateNowAtSetupMs - timestampMs;
+}
+
+function getElapsedMsSinceSetup(): number | undefined {
+    if (dateNowAtSetupMs === undefined) {
+        return undefined;
+    }
+    return Math.max(Date.now() - dateNowAtSetupMs, performance.now() - performanceNowAtSetupMs);
+}
+
+function getMsSinceJsStartup(): number | undefined {
+    const elapsedMs = getElapsedMsSinceSetup();
+    return elapsedMs === undefined ? undefined : Math.round(elapsedMs);
+}
+
+function getMsSinceNativeAppStart(): number | undefined {
+    const elapsedMs = getElapsedMsSinceSetup();
+    if (appStartAgeAtSetupMs === undefined || elapsedMs === undefined) {
+        return undefined;
+    }
+    return Math.round(appStartAgeAtSetupMs + elapsedMs);
+}
+
+export {getMsSinceJsStartup, getMsSinceNativeAppStart, setNativeAppStartTime};

src/pages/iou/request/step/IOURequestStepScan/components/Camera/index.native.tsx

@@ -15,6 +15,7 @@ import HapticFeedback from '@libs/HapticFeedback';
 import Log from '@libs/Log';
 import ReceiptStorage from '@libs/ReceiptStorage';
 import {cancelSpan, endSpanWithAttributes, getSpan, startSpan} from '@libs/telemetry/activeSpans';
+import {getMsSinceJsStartup, getMsSinceNativeAppStart} from '@libs/telemetry/nativeAppStartTime';
 
 import captureReceipt, {shouldTakePhoto} from '@pages/iou/request/step/IOURequestStepScan/captureReceipt';
 import CameraPermissionPrompt from '@pages/iou/request/step/IOURequestStepScan/components/CameraPermissionPrompt';
@@ -126,11 +127,24 @@ function Camera({onCapture, onPicked, shouldAcceptMultipleFiles = false, onLayou
     };
 
     const capturePhoto = () => {
+        const isPhotoCapture = shouldTakePhoto({flash, hasFlash, isInLandscapeMode});
+        const captureAttributes = {
+            [CONST.TELEMETRY.ATTRIBUTE_CAPTURE_METHOD]: isPhotoCapture ? CONST.TELEMETRY.CAPTURE_METHOD.PHOTO : CONST.TELEMETRY.CAPTURE_METHOD.SNAPSHOT,
+            [CONST.TELEMETRY.ATTRIBUTE_FLASH_USED]: flash && hasFlash,
+        };
+
         if (!isMultiScanEnabled) {
+            const msSinceNativeAppStart = getMsSinceNativeAppStart();
+            const msSinceJsStartup = getMsSinceJsStartup();
             startSpan(CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION, {
                 name: CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION,
                 op: CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION,
-                attributes: {[CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE},
+                attributes: {
+                    [CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE,
+                    ...captureAttributes,
+                    ...(msSinceNativeAppStart !== undefined && {[CONST.TELEMETRY.ATTRIBUTE_DURATION_SINCE_NATIVE_APP_STARTUP_MS]: msSinceNativeAppStart}),
+                    ...(msSinceJsStartup !== undefined && {[CONST.TELEMETRY.ATTRIBUTE_DURATION_SINCE_JS_STARTUP_MS]: msSinceJsStartup}),
+                },
             });
         }
 
@@ -155,16 +169,13 @@ function Camera({onCapture, onPicked, shouldAcceptMultipleFiles = false, onLayou
             return;
         }
 
-        const isPhotoCapture = shouldTakePhoto({flash, hasFlash, isInLandscapeMode});
-
         startSpan(CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE, {
             name: CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE,
             op: CONST.TELEMETRY.SPAN_RECEIPT_CAPTURE,
             parentSpan: getSpan(CONST.TELEMETRY.SPAN_SHUTTER_TO_CONFIRMATION),
             attributes: {
                 [CONST.TELEMETRY.ATTRIBUTE_PLATFORM]: CONST.TELEMETRY.SPAN_PLATFORM.NATIVE,
-                [CONST.TELEMETRY.ATTRIBUTE_CAPTURE_METHOD]: isPhotoCapture ? CONST.TELEMETRY.CAPTURE_METHOD.PHOTO : CONST.TELEMETRY.CAPTURE_METHOD.SNAPSHOT,
-                [CONST.TELEMETRY.ATTRIBUTE_FLASH_USED]: flash && hasFlash,
+                ...captureAttributes,
             },
         });
 

src/setup/telemetry/index.native.ts

@@ -1,5 +1,6 @@
 import Log from '@libs/Log';
 import {startSpan} from '@libs/telemetry/activeSpans';
+import {setNativeAppStartTime} from '@libs/telemetry/nativeAppStartTime';
 
 import CONST from '@src/CONST';
 
@@ -102,6 +103,7 @@ export default function (): void {
         Log.warn('[Telemetry] Failed to read native app start time from NitroModule', {error});
         nativeAppStartTimeMs = undefined;
     }
+    setNativeAppStartTime(nativeAppStartTimeMs);
 
     const startupSpan = startSpan(CONST.TELEMETRY.SPAN_APP_STARTUP, {
         name: CONST.TELEMETRY.SPAN_APP_STARTUP,

tests/unit/telemetryStartupMarkersTest.ts

@@ -1,3 +1,5 @@
+import {getMsSinceJsStartup, getMsSinceNativeAppStart} from '@libs/telemetry/nativeAppStartTime';
+
 import setupTelemetry from '@src/setup/telemetry/index.native';
 
 // jest/setup.ts mocks '@src/setup/telemetry' globally; unmock (hoisted above imports) so we exercise the real native implementation.
@@ -37,6 +39,7 @@ describe('telemetry startup markers (native)', () => {
         jest.clearAllMocks();
         // Keep "now" close to the mocked appStartTime so the prewarm staleness guard accepts it.
         jest.spyOn(Date, 'now').mockReturnValue(2_000);
+        jest.spyOn(performance, 'now').mockReturnValue(10_000);
         global.requestAnimationFrame = jest.fn();
         mockMarkers.mockReturnValue({});
         activeSpansMock.startSpan.mockReturnValue({setAttribute: jest.fn()});
@@ -108,4 +111,98 @@ describe('telemetry startup markers (native)', () => {
         expect(() => setupTelemetry()).not.toThrow();
         expect(startInactiveSpanMock).not.toHaveBeenCalled();
     });
+
+    it('keeps the accepted native start time for spans that start later, such as the scan shutter span', () => {
+        // Given a native start time one second before telemetry setup
+        setupTelemetry();
+
+        // When a span starts 500ms after setup
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then it can read the time since the native app start
+        expect(getMsSinceNativeAppStart()).toBe(1_500);
+    });
+
+    it('ignores wall-clock corrections after setup when reporting the time since the native app start', () => {
+        // Given a native start time one second before telemetry setup
+        setupTelemetry();
+
+        // When the device clock is set back an hour and a span starts 500ms after setup
+        jest.spyOn(Date, 'now').mockReturnValue(2_500 - 60 * 60 * 1000);
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then the duration follows the monotonic clock instead of going negative
+        expect(getMsSinceNativeAppStart()).toBe(1_500);
+    });
+
+    it('counts time the device spent in deep sleep after setup', () => {
+        // Given a native start time one second before telemetry setup
+        setupTelemetry();
+
+        // When the device sleeps for an hour, so performance.now() advances only 500ms while the wall clock advances an hour
+        jest.spyOn(Date, 'now').mockReturnValue(2_000 + 60 * 60 * 1000);
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then the duration includes the sleep instead of reporting a scan right after a cold launch
+        expect(getMsSinceNativeAppStart()).toBe(1_000 + 60 * 60 * 1000);
+    });
+
+    it('counts a forward clock correction after setup as elapsed time, an accepted limitation', () => {
+        // Given a native start time one second before telemetry setup
+        setupTelemetry();
+
+        // When the device clock jumps forward an hour and a span starts 500ms after setup
+        jest.spyOn(Date, 'now').mockReturnValue(2_500 + 60 * 60 * 1000);
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then the hour is included, because JS cannot tell a forward correction apart from deep sleep
+        expect(getMsSinceNativeAppStart()).toBe(1_500 + 60 * 60 * 1000);
+    });
+
+    it('drops the native start time of a prewarmed process so later spans report no duration', () => {
+        // Given a native start time older than the prewarm threshold, as on a prewarmed process
+        jest.spyOn(Date, 'now').mockReturnValue(1_000 + 60 * 1000 + 1);
+
+        // When telemetry setup discards it
+        setupTelemetry();
+
+        // Then later spans get no duration instead of minutes or hours
+        expect(getMsSinceNativeAppStart()).toBeUndefined();
+    });
+
+    it('reports the time since JS startup even when the native start time is discarded', () => {
+        // Given an old native process, as when a HybridApp user opens NewDot after more than a minute in OldDot
+        jest.spyOn(Date, 'now').mockReturnValue(1_000 + 60 * 1000 + 1);
+        setupTelemetry();
+
+        // When a span starts 500ms after setup
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then the JS-startup duration is still reported, so these sessions can be told apart from true cold launches
+        expect(getMsSinceNativeAppStart()).toBeUndefined();
+        expect(getMsSinceJsStartup()).toBe(500);
+    });
+
+    it('counts deep sleep in the time since JS startup', () => {
+        // Given telemetry setup has run
+        setupTelemetry();
+
+        // When the device sleeps for an hour, so performance.now() advances only 500ms while the wall clock advances an hour
+        jest.spyOn(Date, 'now').mockReturnValue(2_000 + 60 * 60 * 1000);
+        jest.spyOn(performance, 'now').mockReturnValue(10_500);
+
+        // Then the duration includes the sleep, like the native duration
+        expect(getMsSinceJsStartup()).toBe(60 * 60 * 1000);
+    });
+
+    it('reports no JS-startup duration before telemetry setup has run', () => {
+        // Given a fresh module that telemetry setup has not touched yet
+        jest.isolateModules(() => {
+            const {getMsSinceJsStartup: getMsSinceJsStartupBeforeSetup} = jest.requireActual<{getMsSinceJsStartup: typeof getMsSinceJsStartup}>('@libs/telemetry/nativeAppStartTime');
+
+            // When a span reads the duration
+            // Then there is no value, instead of a time measured from an unset origin
+            expect(getMsSinceJsStartupBeforeSetup()).toBeUndefined();
+        });
+    });
 });