Skip to content

Commit 14c054c

Browse files
antonisclaude
andcommitted
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>
1 parent a5000dc commit 14c054c

2 files changed

Lines changed: 126 additions & 2 deletions

File tree

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: 100 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -40,7 +40,7 @@ const mockedAppState = AppState as jest.Mocked<typeof AppState & MockAppState>;
4040

4141
describe('startIdleNavigationSpan', () => {
4242
beforeEach(() => {
43-
jest.useFakeTimers();
43+
jest.useFakeTimers({ doNotFake: ['performance'] });
4444
NATIVE.enableNative = true;
4545
mockedAppState.isAvailable = true;
4646
mockedAppState.currentState = 'active';
@@ -217,6 +217,105 @@ describe('startIdleNavigationSpan', () => {
217217
});
218218
});
219219

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

0 commit comments

Comments
 (0)