fix(core): Measure callback-style native module calls until completion

CHANGELOG.md

@@ -10,6 +10,10 @@
 
 ### Fixes
 
+- Measure callback-style native module calls until their completion callback fires ([#6561](https://github.com/getsentry/sentry-react-native/pull/6561))
+
+  Bridge methods that report completion through success/failure callbacks instead of a Promise return `undefined`, so they were recorded as sync calls with a near-zero duration. Their `turbo_module.*` durations are now correct, and slow ones produce a `native.turbo_module` breadcrumb. On the Old Architecture a failure callback is also counted as an error, following React Native's own `(failure, success)` trailing-argument convention.
+
 - Make the `RNSentry` SPEC CHECKSUM in `Podfile.lock` machine-independent ([#6534](https://github.com/getsentry/sentry-react-native/pull/6534))
 
   The prebuilt `Sentry.xcframework` is now referenced through a `$(PODS_ROOT)/sentry-xcframeworks/…` symlink instead of the absolute per-user cache path, so `Podfile.lock` no longer churns between developers and CI. Expect a one-time `RNSentry` checksum change on the next `pod install`; the `SENTRY_XCFRAMEWORK_CACHE_DIR=/tmp/…` workaround is no longer needed.

packages/core/src/js/turbomodule/turboModuleCallbacks.ts

@@ -0,0 +1,257 @@
+/**
+ * Instrumentation for callback-style native module methods.
+ *
+ * `wrapTurboModule` can only close a call record on its own for two shapes: a
+ * plain sync return, and a thenable return. Bridge methods that report
+ * completion through success/failure callbacks return `undefined` — the
+ * dominant async shape on the Old Architecture, and still used by some
+ * TurboModules — so without this layer they collapse to ~0ms sync calls.
+ *
+ * See https://github.com/getsentry/sentry-react-native/issues/6542.
+ */
+
+import { debug } from '@sentry/core';
+
+import type { TurboModuleCallKind } from './turboModuleTracker';
+
+import { recordTurboModuleCall, type TurboModuleArch } from './turboModuleAggregator';
+
+/**
+ * Cap on callback-style calls awaiting their completion callback. A callback
+ * that is never invoked would otherwise pin its state forever, so the oldest
+ * entry is closed out without a duration once the cap is reached.
+ */
+export const MAX_PENDING_CALLBACK_CALLS = 1024;
+
+/**
+ * A completion callback that fires later than this is treated as not being a
+ * completion callback at all (e.g. a long-lived subscription handler on the New
+ * Architecture, where no `(failure, success)` convention is enforced). The call
+ * is still counted, but with a zero duration, so a multi-minute "duration"
+ * can't poison the aggregate or fire a bogus slow-call breadcrumb.
+ */
+export const CALLBACK_MAX_AGE_MS = 60_000;
+
+/**
+ * How many stale entries a single insert may sweep. Keeps the age sweep
+ * amortised O(1) on the wrap hot path.
+ */
+const CALLBACK_SWEEP_BUDGET = 8;
+
+interface PendingCallbackCall {
+  startedAtMs: number;
+  /** Closes the call without a trustworthy duration; later callbacks no-op. */
+  expire: () => void;
+}
+
+/** Insertion-ordered, so the first entry is always the oldest. */
+let pendingCallbackCalls = new Map<number, PendingCallbackCall>();
+let nextPendingCallbackId = 0;
+
+/** Tests only. */
+export function _resetPendingCallbackCalls(): void {
+  pendingCallbackCalls = new Map();
+  nextPendingCallbackId = 0;
+}
+
+export interface CallbackCallHandle {
+  /** Called once the instrumented method returned without a thenable. */
+  markReturned: () => void;
+  /**
+   * Drops the bookkeeping: later callback invocations become no-ops. Returns
+   * `true` if a record was already emitted, so the caller doesn't double-count.
+   */
+  abandon: () => boolean;
+}
+
+/**
+ * Records a TurboModule invocation, isolated so a failure inside Sentry only
+ * drops the data instead of breaking the user's call.
+ */
+export function safeRecordTurboModuleCall(
+  name: string,
+  method: string,
+  kind: TurboModuleCallKind,
+  durationMs: number,
+  errored: boolean,
+  recordId: number | undefined,
+  arch: TurboModuleArch,
+): void {
+  try {
+    recordTurboModuleCall({
+      name,
+      method,
+      kind,
+      durationMs,
+      errored,
+      recordId,
+      arch,
+    });
+  } catch (e) {
+    debug.warn(`[TurboModuleTracker] record failed for ${name}.${method}: ${String(e)}`);
+  }
+}
+
+/**
+ * Wraps the trailing completion callbacks of `args` in place so the call's
+ * record is emitted when the callback fires rather than when the method
+ * returns. Returns `undefined` when the method isn't callback-shaped, which is
+ * the common case — nothing is allocated on that path.
+ *
+ * React Native's bridge fixes the shape: the last argument is the success
+ * callback, the second-to-last the failure callback, and a non-function
+ * argument may never follow a function one (see `genMethod` in RN's
+ * `Libraries/BatchedBridge/NativeModules.js`). `'promise'`-typed methods never
+ * receive callbacks and are already covered by the thenable path, so they are
+ * skipped outright.
+ */
+export function instrumentTrailingCallbacks(
+  args: unknown[],
+  originalFn: (...a: unknown[]) => unknown,
+  name: string,
+  method: string,
+  startedAtMs: number,
+  recordId: number | undefined,
+  arch: TurboModuleArch,
+): CallbackCallHandle | undefined {
+  const methodType = (originalFn as { type?: unknown }).type;
+  if (methodType === 'promise') {
+    return undefined;
+  }
+
+  const lastIndex = args.length - 1;
+  if (lastIndex < 0 || typeof args[lastIndex] !== 'function') {
+    return undefined;
+  }
+  const failureIndex = lastIndex > 0 && typeof args[lastIndex - 1] === 'function' ? lastIndex - 1 : -1;
+
+  // Only the Old Architecture bridge guarantees that the second-to-last
+  // function is the failure callback. New Architecture TurboModules take
+  // arbitrary callbacks with no such convention, so guessing there would
+  // corrupt `errorCount` — close the record without flagging an error instead.
+  const failureIsError = failureIndex >= 0 && arch === 'legacy' && typeof methodType === 'string';
+
+  let settled = false;
+  let returned = false;
+  let pendingId: number | undefined;
+
+  const settle = (errored: boolean, durationMs: number): void => {
+    if (settled) {
+      return;
+    }
+    settled = true;
+    if (pendingId !== undefined) {
+      pendingCallbackCalls.delete(pendingId);
+      pendingId = undefined;
+    }
+    safeRecordTurboModuleCall(
+      name,
+      method,
+      // A callback that already fired before the method returned means the work
+      // was synchronous (RN's `'sync'` method type invokes callbacks inline).
+      returned ? 'async' : 'sync',
+      durationMs,
+      errored,
+      recordId,
+      arch,
+    );
+  };
+
+  const emit = (errored: boolean): void => {
+    const durationMs = Date.now() - startedAtMs;
+    // A callback firing this late is not a completion callback (e.g. a
+    // long-lived subscription handler), so its "duration" is meaningless.
+    // Still record the call itself — dropping it would hide the method from
+    // the aggregate entirely, which is worse than the pre-fix ~0ms.
+    settle(errored, returned && durationMs > CALLBACK_MAX_AGE_MS ? 0 : durationMs);
+  };
+
+  args[lastIndex] = instrumentCallback(args[lastIndex] as (...a: unknown[]) => unknown, false, emit);
+  if (failureIndex >= 0) {
+    args[failureIndex] = instrumentCallback(args[failureIndex] as (...a: unknown[]) => unknown, failureIsError, emit);
+  }
+
+  return {
+    markReturned: (): void => {
+      returned = true;
+      if (settled) {
+        return;
+      }
+      evictStalePendingCallbackCalls(startedAtMs);
+      pendingId = nextPendingCallbackId++;
+      pendingCallbackCalls.set(pendingId, {
+        startedAtMs,
+        // Closed out before the callback fired: keep the call in the aggregate,
+        // but with no duration we can stand behind.
+        expire: (): void => {
+          pendingId = undefined;
+          settle(false, 0);
+        },
+      });
+    },
+    abandon: (): boolean => {
+      const alreadyRecorded = settled;
+      settled = true;
+      if (pendingId !== undefined) {
+        pendingCallbackCalls.delete(pendingId);
+        pendingId = undefined;
+      }
+      return alreadyRecorded;
+    },
+  };
+}
+
+/**
+ * Returns a stand-in for `callback` that closes the pending record before
+ * handing control to the original. The bookkeeping runs first so the callback's
+ * own body isn't counted as native time, and is isolated so a tracker failure
+ * can never break the user's callback.
+ */
+function instrumentCallback(
+  callback: (...a: unknown[]) => unknown,
+  errored: boolean,
+  emit: (errored: boolean) => void,
+): (...a: unknown[]) => unknown {
+  return function sentryTurboModuleCallback(this: unknown, ...callbackArgs: unknown[]): unknown {
+    try {
+      emit(errored);
+    } catch (e) {
+      debug.warn(`[TurboModuleTracker] callback record failed: ${String(e)}`);
+    }
+    return callback.apply(this, callbackArgs);
+  };
+}
+
+/**
+ * Closes out pending callback calls that aged out, plus the oldest entry when
+ * the cap is reached. Bounded per invocation so the sweep stays amortised O(1)
+ * on the wrap hot path.
+ *
+ * `nowMs` is the current call's start timestamp — taken microseconds ago, so it
+ * saves a `Date.now()` on the hot path at the cost of an imperceptibly
+ * conservative cutoff.
+ */
+function evictStalePendingCallbackCalls(nowMs: number): void {
+  let budget = CALLBACK_SWEEP_BUDGET;
+  for (const [id, pending] of pendingCallbackCalls) {
+    if (budget-- <= 0 || nowMs - pending.startedAtMs <= CALLBACK_MAX_AGE_MS) {
+      break;
+    }
+    pendingCallbackCalls.delete(id);
+    pending.expire();
+  }
+
+  while (pendingCallbackCalls.size >= MAX_PENDING_CALLBACK_CALLS) {
+    const oldest = pendingCallbackCalls.entries().next();
+    if (oldest.done) {
+      break;
+    }
+    const [id, pending] = oldest.value;
+    pendingCallbackCalls.delete(id);
+    pending.expire();
+    debug.log(
+      `[TurboModuleTracker] More than ${MAX_PENDING_CALLBACK_CALLS} callback-style calls awaiting completion — ` +
+        `closing the oldest one without a duration.`,
+    );
+  }
+}

packages/core/src/js/turbomodule/wrapTurboModule.ts

@@ -2,7 +2,12 @@ import { logger } from '@sentry/core';
 
 import type { TurboModuleCallKind } from './turboModuleTracker';
 
-import { notifyTurboModuleCallStart, recordTurboModuleCall, type TurboModuleArch } from './turboModuleAggregator';
+import { notifyTurboModuleCallStart, type TurboModuleArch } from './turboModuleAggregator';
+import {
+  _resetPendingCallbackCalls,
+  instrumentTrailingCallbacks,
+  safeRecordTurboModuleCall,
+} from './turboModuleCallbacks';
 import { popTurboModuleCall, pushTurboModuleCall, relabelTurboModuleCallKind } from './turboModuleTracker';
 
 /**
@@ -14,6 +19,7 @@ let wrappedModules = new WeakSet<object>();
 /** Tests only. */
 export function _resetWrappedModules(): void {
   wrappedModules = new WeakSet<object>();
+  _resetPendingCallbackCalls();
 }
 
 /**
@@ -24,6 +30,11 @@ export function _resetWrappedModules(): void {
  * - Sync methods are tracked as `kind: 'sync'` and popped right after the call.
  * - Async methods (those returning a thenable) are relabelled to `kind: 'async'`
  *   right after the call dispatches and popped when the returned promise settles.
+ * - Callback-style methods (trailing function arguments, no thenable return —
+ *   the dominant async shape on the Old Architecture bridge) have their
+ *   completion callbacks wrapped, so the recorded duration spans until the
+ *   callback fires instead of collapsing to ~0ms. See
+ *   https://github.com/getsentry/sentry-react-native/issues/6542.
  *
  * `skip` can be used to opt specific method names out of tracking (e.g. very
  * hot, no-op methods like RN's `addListener`/`removeListeners` event-emitter
@@ -98,33 +109,59 @@ export function wrapTurboModule<T extends object>(
         logger.warn(`[TurboModuleTracker] notifyStart failed for ${name}.${key}: ${String(e)}`);
       }
 
+      // Must happen before the call: the wrapped callbacks have to be the ones
+      // handed to the native side. Mutates `args` in place, leaving arity and
+      // argument types untouched.
+      const callbackCall = instrumentTrailingCallbacks(args, originalFn, name, key, startedAtMs, recordId, arch);
+
       let result: unknown;
       try {
         result = originalFn.apply(this, args);
       } catch (e) {
+        // A callback that already fired emitted the record itself.
+        const alreadyRecorded = callbackCall?.abandon() === true;
         safePop(callId, name, key);
-        safeRecord(name, key, 'sync', startedAtMs, true, recordId, arch);
+        if (!alreadyRecorded) {
+          safeRecordTurboModuleCall(name, key, 'sync', Date.now() - startedAtMs, true, recordId, arch);
+        }
         throw e;
       }
 
       if (isThenable(result)) {
+        // A callback that already fired emitted the record itself — the promise
+        // handlers must not add a second one for the same invocation.
+        const alreadyRecorded = callbackCall?.abandon() === true;
         safeRelabel(callId, 'async', name, key);
         return (result as Promise<unknown>).then(
           value => {
             safePop(callId, name, key);
-            safeRecord(name, key, 'async', startedAtMs, false, recordId, arch);
+            if (!alreadyRecorded) {
+              safeRecordTurboModuleCall(name, key, 'async', Date.now() - startedAtMs, false, recordId, arch);
+            }
             return value;
           },
           err => {
             safePop(callId, name, key);
-            safeRecord(name, key, 'async', startedAtMs, true, recordId, arch);
+            if (!alreadyRecorded) {
+              safeRecordTurboModuleCall(name, key, 'async', Date.now() - startedAtMs, true, recordId, arch);
+            }
             throw err;
           },
         );
       }
 
+      if (callbackCall) {
+        // The crash-attribution frame is popped synchronously either way: a
+        // frame held until a callback that may never fire would risk blaming
+        // this module for an unrelated later native crash. Only the timing
+        // record is deferred.
+        safePop(callId, name, key);
+        callbackCall.markReturned();
+        return result;
+      }
+
       safePop(callId, name, key);
-      safeRecord(name, key, 'sync', startedAtMs, false, recordId, arch);
+      safeRecordTurboModuleCall(name, key, 'sync', Date.now() - startedAtMs, false, recordId, arch);
       return result;
     };
 
@@ -200,30 +237,6 @@ function safeRelabel(callId: number | undefined, kind: TurboModuleCallKind, name
   }
 }
 
-function safeRecord(
-  name: string,
-  method: string,
-  kind: TurboModuleCallKind,
-  startedAtMs: number,
-  errored: boolean,
-  recordId: number | undefined,
-  arch: TurboModuleArch,
-): void {
-  try {
-    recordTurboModuleCall({
-      name,
-      method,
-      kind,
-      durationMs: Date.now() - startedAtMs,
-      errored,
-      recordId,
-      arch,
-    });
-  } catch (e) {
-    logger.warn(`[TurboModuleTracker] record failed for ${name}.${method}: ${String(e)}`);
-  }
-}
-
 function isThenable(value: unknown): value is PromiseLike<unknown> {
   if (!value || (typeof value !== 'object' && typeof value !== 'function')) {
     return false;