From 3c07adbd58532cccfb451703dcb28c38cc0690cf Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Fri, 13 Mar 2026 15:31:02 +0100 Subject: [PATCH 1/5] fix(tracing): Fix native frames measurements dropped for idle transactions The NativeFrames integration was dropping transaction-level frame measurements (frames_total, frames_slow, frames_frozen) for all idle transactions because the fallback child span end frames were either unavailable or had mismatched timestamps when processEvent ran. Three issues fixed: - Race condition: child span end frames stored after async awaits, so processEvent could run before data was available. Now stores a Promise immediately before any awaits. - Timestamp mismatch: used wall-clock time (timestampInSeconds) instead of actual span timestamp (spanToJSON), causing isClose check to fail when comparing against the trimmed event.timestamp. - Concurrent transaction interference: single global variable overwritten by any transaction's child spans. Now scoped per root span using AsyncExpiringMap. Co-Authored-By: Claude Opus 4.6 --- .../js/tracing/integrations/nativeFrames.ts | 56 ++++++++++------ .../tracing/integrations/nativeframes.test.ts | 65 +++++++++++++++++++ 2 files changed, 102 insertions(+), 19 deletions(-) diff --git a/packages/core/src/js/tracing/integrations/nativeFrames.ts b/packages/core/src/js/tracing/integrations/nativeFrames.ts index d46b350954..e8f266e929 100644 --- a/packages/core/src/js/tracing/integrations/nativeFrames.ts +++ b/packages/core/src/js/tracing/integrations/nativeFrames.ts @@ -1,5 +1,5 @@ import type { Client, Event, Integration, Measurements, MeasurementUnit, Span } from '@sentry/core'; -import { debug, timestampInSeconds } from '@sentry/core'; +import { debug, getRootSpan, spanToJSON, timestampInSeconds } from '@sentry/core'; import type { NativeFramesResponse } from '../../NativeRNSentry'; import { AsyncExpiringMap } from '../../utils/AsyncExpiringMap'; import { isRootSpan } from '../../utils/span'; @@ -58,8 +58,11 @@ export const createNativeFramesIntegrations = (enable: boolean | undefined): Int * and frame data (frames.total, frames.slow, frames.frozen) onto all spans. */ export const nativeFramesIntegration = (): Integration => { - /** The native frames at the finish time of the most recent span. */ - let _lastChildSpanEndFrames: NativeFramesResponseWithTimestamp | null = null; + /** The native frames at the finish time of the most recent child span, keyed by root span ID. + * Stores promises so the data is available for processEvent to await even before + * the async native bridge call completes. */ + const _lastChildSpanEndFramesByRootSpan: AsyncExpiringMap = + new AsyncExpiringMap({ ttl: START_FRAMES_TIMEOUT_MS }); const _spanToNativeFramesAtStartMap: AsyncExpiringMap = new AsyncExpiringMap({ ttl: START_FRAMES_TIMEOUT_MS, }); @@ -109,7 +112,6 @@ export const nativeFramesIntegration = (): Integration => { * produce incorrect deltas. The native bridge calls are async and non-blocking. */ const fetchEndFramesForSpan = async (span: Span): Promise => { - const timestamp = timestampInSeconds(); const spanId = span.spanContext().spanId; const hasStartFrames = _spanToNativeFramesAtStartMap.has(spanId); @@ -118,8 +120,31 @@ export const nativeFramesIntegration = (): Integration => { return; } + // For child spans: immediately store a promise for fallback end frames before any awaits, + // so processEvent can find and await it even if this async function hasn't completed yet. + // Uses the actual span timestamp (not wall-clock time) so it matches the trimmed event.timestamp + // for idle transactions. Scoped per root span to avoid concurrent transaction interference. + let childEndFramesPromise: Promise | undefined; + if (!isRootSpan(span)) { + const rootSpanId = getRootSpan(span).spanContext().spanId; + const spanTimestamp = spanToJSON(span).timestamp; + if (spanTimestamp) { + childEndFramesPromise = fetchNativeFrames(); + _lastChildSpanEndFramesByRootSpan.set( + rootSpanId, + childEndFramesPromise + .then(frames => ({ timestamp: spanTimestamp, nativeFrames: frames })) + .then(undefined, error => { + debug.log(`[${INTEGRATION_NAME}] Error while fetching child span end frames.`, error); + return null; + }), + ); + } + } + if (isRootSpan(span)) { // Root spans: Store end frames for transaction measurements (backward compatibility) + const timestamp = timestampInSeconds(); debug.log(`[${INTEGRATION_NAME}] Fetch frames for root span end (${spanId}).`); _spanToNativeFramesAtEndMap.set( spanId, @@ -147,10 +172,10 @@ export const nativeFramesIntegration = (): Integration => { return; } - // NOTE: For root spans, this is the second call to fetchNativeFrames() for the same span. + // For child spans, reuse the already-kicked-off promise to avoid a redundant native bridge call. + // For root spans, this is the second call to fetchNativeFrames() for the same span. // The calls are very close together (microseconds apart), so inconsistency is minimal. - // Future optimization: reuse the first call's promise to avoid redundant native bridge call. - const endFrames = await fetchNativeFrames(); + const endFrames = childEndFramesPromise ? await childEndFramesPromise : await fetchNativeFrames(); // Calculate deltas const totalFrames = endFrames.totalFrames - startFrames.totalFrames; @@ -166,14 +191,6 @@ export const nativeFramesIntegration = (): Integration => { `[${INTEGRATION_NAME}] Attached frame data to span ${spanId}: total=${totalFrames}, slow=${slowFrames}, frozen=${frozenFrames}`, ); } - - // Update last child span end frames for root span fallback logic - if (!isRootSpan(span)) { - _lastChildSpanEndFrames = { - timestamp, - nativeFrames: endFrames, - }; - } } catch (error) { debug.log(`[${INTEGRATION_NAME}] Error while capturing end frames for span ${spanId}.`, error); } @@ -202,17 +219,18 @@ export const nativeFramesIntegration = (): Integration => { } const endFrames = await _spanToNativeFramesAtEndMap.pop(spanId); + const lastChildFrames = await _lastChildSpanEndFramesByRootSpan.pop(spanId); let finalEndFrames: NativeFramesResponse | undefined; if (endFrames && isClose(endFrames.timestamp, event.timestamp)) { // Must be in the margin of error of the actual transaction finish time (finalEndTimestamp) debug.log(`[${INTEGRATION_NAME}] Using frames from root span end (spanId, ${spanId}).`); finalEndFrames = endFrames.nativeFrames; - } else if (_lastChildSpanEndFrames && isClose(_lastChildSpanEndFrames.timestamp, event.timestamp)) { - // Fallback to the last span finish if it is within the margin of error of the actual finish timestamp. - // This should be the case for trimEnd. + } else if (lastChildFrames && isClose(lastChildFrames.timestamp, event.timestamp)) { + // Fallback to the last child span finish if it is within the margin of error of the actual finish timestamp. + // This handles idle transactions where event.timestamp is trimmed to the last child span's end time. debug.log(`[${INTEGRATION_NAME}] Using native frames from last child span end (spanId, ${spanId}).`); - finalEndFrames = _lastChildSpanEndFrames.nativeFrames; + finalEndFrames = lastChildFrames.nativeFrames; } else { debug.warn( `[${INTEGRATION_NAME}] Frames were collected within larger than margin of error delay for spanId (${spanId}). Dropping the inaccurate values.`, diff --git a/packages/core/test/tracing/integrations/nativeframes.test.ts b/packages/core/test/tracing/integrations/nativeframes.test.ts index 28c257b010..db92174399 100644 --- a/packages/core/test/tracing/integrations/nativeframes.test.ts +++ b/packages/core/test/tracing/integrations/nativeframes.test.ts @@ -332,6 +332,71 @@ describe('NativeFramesInstrumentation', () => { expect(childSpan!.data).not.toHaveProperty('frames.frozen'); }); + it('falls back to last child span end frames when root span end timestamp does not match event timestamp (idle transaction trim)', async () => { + // Simulate idle transaction trimming: an event processor before NativeFrames shifts + // event.timestamp back to the child span's end time. This makes the root span's end frames + // timestamp (captured at idle timeout) no longer match within the 50ms margin of error, + // forcing processEvent to fall back to the child span's end frames. + let childEndTimestamp: number | undefined; + asyncProcessorBeforeNativeFrames = async (event: Event) => { + if (event.timestamp && childEndTimestamp) { + event.timestamp = childEndTimestamp; // Trim to child span end time (simulates idle trimEnd) + } + return event; + }; + + const rootStartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 }; + const childStartFrames = { totalFrames: 110, slowFrames: 11, frozenFrames: 6 }; + const childEndFrames = { totalFrames: 160, slowFrames: 16, frozenFrames: 8 }; + const rootEndFrames = { totalFrames: 200, slowFrames: 20, frozenFrames: 10 }; + + mockFunction(NATIVE.fetchNativeFrames) + .mockResolvedValueOnce(rootStartFrames) // root span start + .mockResolvedValueOnce(childStartFrames) // child span start + .mockResolvedValueOnce(childEndFrames) // child span end (fallback + span attributes) + .mockResolvedValueOnce(rootEndFrames) // root span end (stored in endMap) + .mockResolvedValueOnce(rootEndFrames); // root span end (for span attributes) + + await startSpan({ name: 'idle-transaction' }, async () => { + startSpan({ name: 'child-activity' }, childSpan => { + // Child span ends here at current mock time + childEndTimestamp = Date.now() / 1000; + }); + await Promise.resolve(); // Flush frame captures + await Promise.resolve(); + await Promise.resolve(); + + // Advance time to simulate idle timeout gap (1 second > 50ms margin) + global.Date.now = jest.fn(() => mockDate.getTime() + 1000); + // Root span ends here at the advanced time + }); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + // The root span end frames timestamp won't match event.timestamp (off by 1s > 50ms margin), + // so processEvent falls back to the child span end frames. + // measurements = childEndFrames - rootStartFrames + expect(client.event!).toEqual( + expect.objectContaining>({ + measurements: expect.objectContaining({ + frames_total: { + value: 60, // 160 - 100 + unit: 'none', + }, + frames_slow: { + value: 6, // 16 - 10 + unit: 'none', + }, + frames_frozen: { + value: 3, // 8 - 5 + unit: 'none', + }, + }), + }), + ); + }); + it('attaches frame data to multiple child spans', async () => { const rootStartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 }; const child1StartFrames = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 }; From 32f98500740ccbb5464ae2fda0fd3e5e5431e5d6 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Fri, 13 Mar 2026 15:36:13 +0100 Subject: [PATCH 2/5] docs: Add changelog entry for native frames race condition fix Co-Authored-By: Claude Opus 4.6 --- CHANGELOG.md | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index add9b2b74e..bc2b4cc5ee 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,12 @@ > make sure you follow our [migration guide](https://docs.sentry.io/platforms/react-native/migration/) first. +## Unreleased + +### Fixes + +- Fix native frames measurements being dropped due to race condition ([#5813](https://github.com/getsentry/sentry-react-native/pull/5813)) + ## 8.4.0 ### Fixes From ff103c38f21853d9378941efee15abb64be469c5 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Fri, 13 Mar 2026 15:52:12 +0100 Subject: [PATCH 3/5] fix(lint): Remove unused childSpan parameter in test Co-Authored-By: Claude Opus 4.6 --- packages/core/test/tracing/integrations/nativeframes.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/test/tracing/integrations/nativeframes.test.ts b/packages/core/test/tracing/integrations/nativeframes.test.ts index db92174399..b1336251ad 100644 --- a/packages/core/test/tracing/integrations/nativeframes.test.ts +++ b/packages/core/test/tracing/integrations/nativeframes.test.ts @@ -358,7 +358,7 @@ describe('NativeFramesInstrumentation', () => { .mockResolvedValueOnce(rootEndFrames); // root span end (for span attributes) await startSpan({ name: 'idle-transaction' }, async () => { - startSpan({ name: 'child-activity' }, childSpan => { + startSpan({ name: 'child-activity' }, () => { // Child span ends here at current mock time childEndTimestamp = Date.now() / 1000; }); From 88cae026653692d9a789624e2ca74fc871a97b2f Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Mon, 16 Mar 2026 10:05:05 +0100 Subject: [PATCH 4/5] fix(tracing): Remove duplicate error log for child span end frames The error is already logged by the catch block at line 191, so the separate log in the promise chain was redundant. Co-Authored-By: Claude Opus 4.6 (1M context) --- packages/core/src/js/tracing/integrations/nativeFrames.ts | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/packages/core/src/js/tracing/integrations/nativeFrames.ts b/packages/core/src/js/tracing/integrations/nativeFrames.ts index e8f266e929..77b31edd63 100644 --- a/packages/core/src/js/tracing/integrations/nativeFrames.ts +++ b/packages/core/src/js/tracing/integrations/nativeFrames.ts @@ -134,10 +134,7 @@ export const nativeFramesIntegration = (): Integration => { rootSpanId, childEndFramesPromise .then(frames => ({ timestamp: spanTimestamp, nativeFrames: frames })) - .then(undefined, error => { - debug.log(`[${INTEGRATION_NAME}] Error while fetching child span end frames.`, error); - return null; - }), + .then(undefined, () => null), ); } } From 2d53119d0d9b5a2b0c175e0ca95d077430b95a42 Mon Sep 17 00:00:00 2001 From: Antonis Lilis Date: Mon, 16 Mar 2026 10:19:10 +0100 Subject: [PATCH 5/5] test(tracing): Add test for concurrent transaction frame interference Verifies that child end frames are scoped per root span ID and don't leak between overlapping transactions. Co-Authored-By: Claude Opus 4.6 (1M context) --- .../tracing/integrations/nativeframes.test.ts | 73 +++++++++++++++++++ 1 file changed, 73 insertions(+) diff --git a/packages/core/test/tracing/integrations/nativeframes.test.ts b/packages/core/test/tracing/integrations/nativeframes.test.ts index b1336251ad..327facc995 100644 --- a/packages/core/test/tracing/integrations/nativeframes.test.ts +++ b/packages/core/test/tracing/integrations/nativeframes.test.ts @@ -447,4 +447,77 @@ describe('NativeFramesInstrumentation', () => { }), ); }); + + it('does not mix up child end frames between overlapping transactions', async () => { + // During txn-1's event processing, txn-2 starts and its child ends, + // writing to the per-root-span map. txn-1's processEvent should still + // read its own child's end frames, not txn-2's. + let txn1ChildEndTimestamp: number | undefined; + + const txn2RootStart = { totalFrames: 900, slowFrames: 90, frozenFrames: 45 }; + const txn2ChildStart = { totalFrames: 910, slowFrames: 91, frozenFrames: 46 }; + const txn2ChildEnd = { totalFrames: 950, slowFrames: 95, frozenFrames: 48 }; + const txn2RootEnd = { totalFrames: 999, slowFrames: 99, frozenFrames: 49 }; + + asyncProcessorBeforeNativeFrames = async (event: Event) => { + if (event.transaction === 'txn-1' && txn1ChildEndTimestamp) { + event.timestamp = txn1ChildEndTimestamp; // Simulate idle trim + + // Start and complete txn-2 during txn-1's event processing. + // With a global variable (old code), txn-2's child end would overwrite txn-1's data. + // Clear scope so txn-2 is a new root span, not a child of txn-1. + getCurrentScope().clear(); + await startSpan({ name: 'txn-2' }, async () => { + startSpan({ name: 'txn-2-child' }, () => {}); + await Promise.resolve(); + await Promise.resolve(); + }); + } + return event; + }; + + const txn1RootStart = { totalFrames: 100, slowFrames: 10, frozenFrames: 5 }; + const txn1ChildStart = { totalFrames: 110, slowFrames: 11, frozenFrames: 6 }; + const txn1ChildEnd = { totalFrames: 160, slowFrames: 16, frozenFrames: 8 }; + const txn1RootEnd = { totalFrames: 200, slowFrames: 20, frozenFrames: 10 }; + + mockFunction(NATIVE.fetchNativeFrames) + .mockResolvedValueOnce(txn1RootStart) // txn-1 root start + .mockResolvedValueOnce(txn1ChildStart) // txn-1 child start + .mockResolvedValueOnce(txn1ChildEnd) // txn-1 child end + .mockResolvedValueOnce(txn1RootEnd) // txn-1 root end (endMap) + .mockResolvedValueOnce(txn1RootEnd) // txn-1 root end (span attributes) + // txn-2 mocks (consumed during txn-1's async processor) + .mockResolvedValueOnce(txn2RootStart) // txn-2 root start + .mockResolvedValueOnce(txn2ChildStart) // txn-2 child start + .mockResolvedValueOnce(txn2ChildEnd) // txn-2 child end + .mockResolvedValueOnce(txn2RootEnd) // txn-2 root end (endMap) + .mockResolvedValueOnce(txn2RootEnd); // txn-2 root end (span attributes) + + await startSpan({ name: 'txn-1' }, async () => { + startSpan({ name: 'txn-1-child' }, () => { + txn1ChildEndTimestamp = Date.now() / 1000; + }); + await Promise.resolve(); + await Promise.resolve(); + await Promise.resolve(); + // Advance time to simulate idle timeout (root end timestamp won't match child end) + global.Date.now = jest.fn(() => mockDate.getTime() + 1000); + }); + + await jest.runOnlyPendingTimersAsync(); + await client.flush(); + + // txn-1 should use its own child end frames, not txn-2's + // measurements = txn1ChildEnd - txn1RootStart + const txn1Event = client.eventQueue.find(e => e.transaction === 'txn-1'); + expect(txn1Event).toBeDefined(); + expect(txn1Event!.measurements).toEqual( + expect.objectContaining({ + frames_total: { value: 60, unit: 'none' }, // 160 - 100 + frames_slow: { value: 6, unit: 'none' }, // 16 - 10 + frames_frozen: { value: 3, unit: 'none' }, // 8 - 5 + }), + ); + }); });