Skip to content

Commit df5d108

Browse files
antonisclaude
andauthored
fix(tracing): Fix inflated http.client span durations on iOS background cancellation (#5944)
* fix(tracing): Use foreground-exit timestamp for http.client spans on iOS background cancellation On iOS, when the app goes inactive, `cancelInBackground` schedules a 5-second deferred cancellation timer. If the JS thread is suspended between the `inactive` and `background` transitions, the timer fires only after JS resumes — potentially seconds or minutes later. The idle span's `onIdleSpanEnded` then force-ends all still-recording child spans with this late timestamp, producing http.client spans with inflated durations that don't match the corresponding breadcrumbs. This was reported by a customer whose traces showed http.client spans with long durations and `cancelled` status, while the app was marked as "In Foreground" with no backgrounding breadcrumb — the hallmark of the iOS inactive timer race. The fix records `timestampInSeconds()` when the app first leaves the foreground (`inactive` or `background` event) and uses that timestamp to end http.client child spans in `cancelSpan()`, before the parent idle span ends. This prevents `onIdleSpanEnded` from overwriting them with the later timer-fire timestamp. Fixes #5942 Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> * docs: Add changelog entry for http.client span duration fix Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> * fix(tracing): Remove unused variable in test Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> * fix(tracing): Make timestamp reset test independent of fake timer clock The test was asserting on duration ranges (>2s, <5s) which relied on jest.advanceTimersByTime advancing the value returned by timestampInSeconds(). Since performance is not faked, this only works when the cached time function falls back to Date.now() — a fragile implementation detail. Instead, capture timestampInSeconds() at each state transition and compare the span's end time directly against the background timestamp. Co-Authored-By: Claude Opus 4.6 (1M context) <noreply@anthropic.com> * Lint fix --------- Co-authored-by: Claude Opus 4.6 (1M context) <noreply@anthropic.com>
1 parent 4ae2ca9 commit df5d108

File tree

3 files changed

+140
-3
lines changed

3 files changed

+140
-3
lines changed

CHANGELOG.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717

1818
### Fixes
1919

20+
- Fix inflated `http.client` span durations on iOS when the app backgrounds during a request ([#5944](https://github.com/getsentry/sentry-react-native/pull/5944))
2021
- Fix crash caused by nullish response in supabase PostgREST handler ([#5938](https://github.com/getsentry/sentry-react-native/pull/5938))
2122
- Fix iOS crash (EXC_BAD_ACCESS) in time-to-initial-display when navigating between screens ([#5887](https://github.com/getsentry/sentry-react-native/pull/5887))
2223

packages/core/src/js/tracing/onSpanEndUtils.ts

Lines changed: 26 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
import type { Client, Span } from '@sentry/core';
22
import type { AppStateStatus } from 'react-native';
33

4-
import { debug, getSpanDescendants, SPAN_STATUS_ERROR, spanToJSON } from '@sentry/core';
4+
import { debug, getSpanDescendants, SPAN_STATUS_ERROR, spanToJSON, timestampInSeconds } from '@sentry/core';
55
import { AppState, Platform } from 'react-native';
66

77
import { isRootSpan, isSentrySpan } from '../utils/span';
@@ -198,20 +198,44 @@ export const onlySampleIfChildSpans = (client: Client, span: Span): void => {
198198
export const cancelInBackground = (client: Client, span: Span): void => {
199199
let inactiveTimeout: ReturnType<typeof setTimeout> | undefined;
200200

201+
// The timestamp when the app actually left the foreground. Used to end
202+
// http.client child spans at the right time instead of whenever the
203+
// deferred cancellation timer fires (which can be much later if the JS
204+
// thread was suspended on iOS).
205+
let leftForegroundTimestamp: number | undefined;
206+
201207
const cancelSpan = (): void => {
202208
if (inactiveTimeout !== undefined) {
203209
clearTimeout(inactiveTimeout);
204210
inactiveTimeout = undefined;
205211
}
206212
debug.log(`Setting ${spanToJSON(span).op} transaction to cancelled because the app is in the background.`);
213+
214+
// End still-recording http.client children at the time the app left
215+
// the foreground, not when the deferred timer fires. On iOS, the JS
216+
// thread can be suspended after the `inactive` event, so the 5-second
217+
// timer may fire long after the app backgrounded. Using the original
218+
// timestamp prevents inflated span durations.
219+
const childEndTimestamp = leftForegroundTimestamp ?? timestampInSeconds();
220+
const children = getSpanDescendants(span);
221+
for (const child of children) {
222+
if (child !== span && child.isRecording() && spanToJSON(child).op === 'http.client') {
223+
child.setStatus({ code: SPAN_STATUS_ERROR, message: 'cancelled' });
224+
child.end(childEndTimestamp);
225+
}
226+
}
227+
207228
span.setStatus({ code: SPAN_STATUS_ERROR, message: 'cancelled' });
208229
span.end();
209230
};
210231

211232
const subscription = AppState.addEventListener('change', (newState: AppStateStatus) => {
212233
if (newState === 'background') {
234+
leftForegroundTimestamp = leftForegroundTimestamp ?? timestampInSeconds();
213235
cancelSpan();
214236
} else if (Platform.OS === 'ios' && newState === 'inactive') {
237+
// Record when the app actually left the foreground.
238+
leftForegroundTimestamp = timestampInSeconds();
215239
// Schedule a deferred cancellation — if the JS thread is suspended
216240
// before the 'background' event fires, this timer will execute when
217241
// the app is eventually resumed and end the span.
@@ -220,6 +244,7 @@ export const cancelInBackground = (client: Client, span: Span): void => {
220244
}
221245
} else if (newState === 'active') {
222246
// App returned to foreground — clear any pending inactive cancellation.
247+
leftForegroundTimestamp = undefined;
223248
if (inactiveTimeout !== undefined) {
224249
clearTimeout(inactiveTimeout);
225250
inactiveTimeout = undefined;

packages/core/test/tracing/idleNavigationSpan.test.ts

Lines changed: 113 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,14 @@
11
import type { Span } from '@sentry/core';
22
import type { AppStateStatus } from 'react-native';
33

4-
import { getActiveSpan, getCurrentScope, spanToJSON, startInactiveSpan, startSpanManual } from '@sentry/core';
4+
import {
5+
getActiveSpan,
6+
getCurrentScope,
7+
spanToJSON,
8+
startInactiveSpan,
9+
startSpanManual,
10+
timestampInSeconds,
11+
} from '@sentry/core';
512
import { AppState } from 'react-native';
613

714
import type { ScopeWithMaybeSpan } from '../../src/js/tracing/span';
@@ -40,7 +47,7 @@ const mockedAppState = AppState as jest.Mocked<typeof AppState & MockAppState>;
4047

4148
describe('startIdleNavigationSpan', () => {
4249
beforeEach(() => {
43-
jest.useFakeTimers();
50+
jest.useFakeTimers({ doNotFake: ['performance'] });
4451
NATIVE.enableNative = true;
4552
mockedAppState.isAvailable = true;
4653
mockedAppState.currentState = 'active';
@@ -217,6 +224,110 @@ describe('startIdleNavigationSpan', () => {
217224
});
218225
});
219226

227+
describe('http.client child spans during background cancellation', () => {
228+
it('ends http.client child at the time the app went inactive, not when the deferred timer fires', () => {
229+
const navSpan = startIdleNavigationSpan({ name: 'test' });
230+
const httpSpan = startInactiveSpan({ name: 'GET /api/data', op: 'http.client' });
231+
const httpStartTime = spanToJSON(httpSpan).start_timestamp;
232+
233+
// App goes inactive at a known time (e.g. user presses home on iOS)
234+
mockedAppState.setState('inactive');
235+
236+
// Simulate JS thread suspension + resume: advance well past the 5s timer.
237+
// In production this delay is caused by the JS thread being suspended
238+
// while the app is in the background, then resumed much later.
239+
jest.advanceTimersByTime(30_000);
240+
241+
expect(spanToJSON(navSpan!).status).toBe('cancelled');
242+
243+
// The http.client span should be ended at approximately when the app
244+
// went inactive, NOT 30 seconds later when the timer fired.
245+
const httpEndTime = spanToJSON(httpSpan).timestamp!;
246+
const httpDuration = httpEndTime - httpStartTime;
247+
expect(httpDuration).toBeLessThan(1);
248+
expect(spanToJSON(httpSpan).status).toBe('cancelled');
249+
});
250+
251+
it('uses fresh timestamp after inactive → active → background cycle', () => {
252+
startIdleNavigationSpan({ name: 'test' });
253+
const httpSpan = startInactiveSpan({ name: 'GET /api/data', op: 'http.client' });
254+
255+
// App goes inactive briefly (e.g. Control Center)
256+
mockedAppState.setState('inactive');
257+
const inactiveTime = timestampInSeconds();
258+
259+
jest.advanceTimersByTime(1_000);
260+
261+
// App returns to active — the inactive timestamp should be reset
262+
mockedAppState.setState('active');
263+
264+
jest.advanceTimersByTime(2_000);
265+
266+
// Now app goes to background — should use this new timestamp, not the old inactive one
267+
const backgroundTime = timestampInSeconds();
268+
mockedAppState.setState('background');
269+
270+
const httpEndTime = spanToJSON(httpSpan).timestamp!;
271+
272+
// The end time should match the background event, not the earlier inactive event.
273+
// Use toBeCloseTo because timestampInSeconds() may advance slightly between calls.
274+
expect(httpEndTime).toBeCloseTo(backgroundTime, 1);
275+
276+
// If the inactive timestamp was NOT reset, the span would have ended
277+
// at inactiveTime instead — verify that's not the case when they differ.
278+
if (Math.abs(backgroundTime - inactiveTime) > 0.01) {
279+
expect(httpEndTime).not.toBeCloseTo(inactiveTime, 1);
280+
}
281+
});
282+
283+
it('ends http.client child at background time on immediate background', () => {
284+
const navSpan = startIdleNavigationSpan({ name: 'test' });
285+
const httpSpan = startInactiveSpan({ name: 'GET /api/data', op: 'http.client' });
286+
287+
// App goes directly to background (Android, or iOS without inactive)
288+
mockedAppState.setState('background');
289+
290+
expect(spanToJSON(navSpan!).status).toBe('cancelled');
291+
expect(spanToJSON(httpSpan).timestamp).toBeDefined();
292+
expect(spanToJSON(httpSpan).status).toBe('cancelled');
293+
});
294+
295+
it('preserves already-ended http.client spans when app backgrounds', () => {
296+
const navSpan = startIdleNavigationSpan({ name: 'test' });
297+
298+
// HTTP request that completed before backgrounding
299+
const httpSpan = startInactiveSpan({ name: 'GET /api/data', op: 'http.client' });
300+
httpSpan.setStatus({ code: 1 }); // OK
301+
httpSpan.end();
302+
303+
const httpEndTimeBefore = spanToJSON(httpSpan).timestamp;
304+
305+
// App goes to background
306+
mockedAppState.setState('background');
307+
308+
expect(spanToJSON(navSpan!).status).toBe('cancelled');
309+
310+
// The already-ended http.client span should be untouched
311+
expect(spanToJSON(httpSpan).status).toBe('ok');
312+
expect(spanToJSON(httpSpan).timestamp).toBe(httpEndTimeBefore);
313+
});
314+
315+
it('still cancels non-http.client children when app backgrounds', () => {
316+
const navSpan = startIdleNavigationSpan({ name: 'test' });
317+
318+
// A non-http span (e.g. a UI rendering span)
319+
const uiSpan = startInactiveSpan({ name: 'ui.render', op: 'ui.load' });
320+
321+
mockedAppState.setState('background');
322+
323+
expect(spanToJSON(navSpan!).status).toBe('cancelled');
324+
325+
// Non-http.client children should still be cancelled by idle span logic
326+
expect(spanToJSON(uiSpan).timestamp).toBeDefined();
327+
expect(spanToJSON(uiSpan).status).toBe('cancelled');
328+
});
329+
});
330+
220331
describe('Start a new active root span (without parent)', () => {
221332
it('Starts a new span when there is no active span', () => {
222333
const span = startIdleNavigationSpan({

0 commit comments

Comments
 (0)