Skip to content

fix(browser): Fix idle span ending #12306

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
May 31, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@ test('Captures a pageload transaction', async ({ page }) => {

const transactionEvent = await transactionEventPromise;
expect(transactionEvent.contexts?.trace).toEqual({
data: expect.objectContaining({
data: {
deviceMemory: expect.any(String),
effectiveConnectionType: expect.any(String),
hardwareConcurrency: expect.any(String),
Expand All @@ -19,7 +19,7 @@ test('Captures a pageload transaction', async ({ page }) => {
'sentry.origin': 'auto.pageload.react.reactrouter_v6',
'sentry.sample_rate': 1,
'sentry.source': 'route',
}),
},
op: 'pageload',
span_id: expect.any(String),
trace_id: expect.any(String),
Expand Down
91 changes: 47 additions & 44 deletions packages/core/src/tracing/idleSpan.ts
Original file line number Diff line number Diff line change
Expand Up @@ -113,37 +113,48 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
const previousActiveSpan = getActiveSpan();
const span = _startIdleSpan(startSpanOptions);

function _endSpan(timestamp: number = timestampInSeconds()): void {
// Ensure we end with the last span timestamp, if possible
const spans = getSpanDescendants(span).filter(child => child !== span);
// We patch span.end to ensure we can run some things before the span is ended
// eslint-disable-next-line @typescript-eslint/unbound-method
span.end = new Proxy(span.end, {
apply(target, thisArg, args: Parameters<Span['end']>) {
if (beforeSpanEnd) {
beforeSpanEnd(span);
}

// If we have no spans, we just end, nothing else to do here
if (!spans.length) {
span.end(timestamp);
return;
}
const timestamp = args[0] || timestampInSeconds();
const spanEndTimestamp = spanTimeInputToSeconds(timestamp);

const childEndTimestamps = spans
.map(span => spanToJSON(span).timestamp)
.filter(timestamp => !!timestamp) as number[];
const latestSpanEndTimestamp = childEndTimestamps.length ? Math.max(...childEndTimestamps) : undefined;

const spanEndTimestamp = spanTimeInputToSeconds(timestamp);
// In reality this should always exist here, but type-wise it may be undefined...
const spanStartTimestamp = spanToJSON(span).start_timestamp;

// The final endTimestamp should:
// * Never be before the span start timestamp
// * Be the latestSpanEndTimestamp, if there is one, and it is smaller than the passed span end timestamp
// * Otherwise be the passed end timestamp
// Final timestamp can never be after finalTimeout
const endTimestamp = Math.min(
spanStartTimestamp ? spanStartTimestamp + finalTimeout / 1000 : Infinity,
Math.max(spanStartTimestamp || -Infinity, Math.min(spanEndTimestamp, latestSpanEndTimestamp || Infinity)),
);

span.end(endTimestamp);
}
// Ensure we end with the last span timestamp, if possible
const spans = getSpanDescendants(span).filter(child => child !== span);

// If we have no spans, we just end, nothing else to do here
if (!spans.length) {
onIdleSpanEnded(spanEndTimestamp);
return Reflect.apply(target, thisArg, args);
}

const childEndTimestamps = spans
.map(span => spanToJSON(span).timestamp)
.filter(timestamp => !!timestamp) as number[];
const latestSpanEndTimestamp = childEndTimestamps.length ? Math.max(...childEndTimestamps) : undefined;

// In reality this should always exist here, but type-wise it may be undefined...
const spanStartTimestamp = spanToJSON(span).start_timestamp;

// The final endTimestamp should:
// * Never be before the span start timestamp
// * Be the latestSpanEndTimestamp, if there is one, and it is smaller than the passed span end timestamp
// * Otherwise be the passed end timestamp
// Final timestamp can never be after finalTimeout
const endTimestamp = Math.min(
spanStartTimestamp ? spanStartTimestamp + finalTimeout / 1000 : Infinity,
Math.max(spanStartTimestamp || -Infinity, Math.min(spanEndTimestamp, latestSpanEndTimestamp || Infinity)),
);

onIdleSpanEnded(endTimestamp);
return Reflect.apply(target, thisArg, [endTimestamp]);
},
});

/**
* Cancels the existing idle timeout, if there is one.
Expand Down Expand Up @@ -173,7 +184,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
_idleTimeoutID = setTimeout(() => {
if (!_finished && activities.size === 0 && _autoFinishAllowed) {
_finishReason = FINISH_REASON_IDLE_TIMEOUT;
_endSpan(endTimestamp);
span.end(endTimestamp);
}
}, idleTimeout);
}
Expand All @@ -186,7 +197,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
_idleTimeoutID = setTimeout(() => {
if (!_finished && _autoFinishAllowed) {
_finishReason = FINISH_REASON_HEARTBEAT_FAILED;
_endSpan(endTimestamp);
span.end(endTimestamp);
}
}, childSpanTimeout);
}
Expand Down Expand Up @@ -223,21 +234,17 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
}
}

function onIdleSpanEnded(): void {
function onIdleSpanEnded(endTimestamp: number): void {
_finished = true;
activities.clear();

if (beforeSpanEnd) {
beforeSpanEnd(span);
}

_setSpanForScope(scope, previousActiveSpan);

const spanJSON = spanToJSON(span);

const { timestamp: endTimestamp, start_timestamp: startTimestamp } = spanJSON;
const { start_timestamp: startTimestamp } = spanJSON;
// This should never happen, but to make TS happy...
if (!endTimestamp || !startTimestamp) {
if (!startTimestamp) {
return;
}

Expand Down Expand Up @@ -267,7 +274,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti

// Add a delta with idle timeout so that we prevent false positives
const timeoutWithMarginOfError = (finalTimeout + idleTimeout) / 1000;
const spanEndedBeforeFinalTimeout = childEndTimestamp - childStartTimestamp < timeoutWithMarginOfError;
const spanEndedBeforeFinalTimeout = childEndTimestamp - childStartTimestamp <= timeoutWithMarginOfError;

if (DEBUG_BUILD) {
const stringifiedSpan = JSON.stringify(childSpan, undefined, 2);
Expand Down Expand Up @@ -312,10 +319,6 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
}

_popActivity(endedSpan.spanContext().spanId);

if (endedSpan === span) {
onIdleSpanEnded();
}
});

client.on('idleSpanEnableAutoFinish', spanToAllowAutoFinish => {
Expand All @@ -338,7 +341,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti
if (!_finished) {
span.setStatus({ code: SPAN_STATUS_ERROR, message: 'deadline_exceeded' });
_finishReason = FINISH_REASON_FINAL_TIMEOUT;
_endSpan();
span.end();
}
}, finalTimeout);

Expand Down
5 changes: 4 additions & 1 deletion packages/core/src/tracing/sentrySpan.ts
Original file line number Diff line number Diff line change
Expand Up @@ -342,7 +342,10 @@ export class SentrySpan implements Span {

if (hasMeasurements) {
DEBUG_BUILD &&
logger.log('[Measurements] Adding measurements to transaction', JSON.stringify(measurements, undefined, 2));
logger.log(
'[Measurements] Adding measurements to transaction event',
JSON.stringify(measurements, undefined, 2),
);
transaction.measurements = measurements;
}

Expand Down
12 changes: 8 additions & 4 deletions packages/core/test/lib/tracing/idleSpan.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -122,9 +122,9 @@ describe('startIdleSpan', () => {
span.setAttribute('foo', 'bar');
// Try adding a child here - we do this in browser tracing...
const inner = startInactiveSpan({ name: 'from beforeSpanEnd', startTime: baseTimeInSeconds });
inner?.end(baseTimeInSeconds);
inner.end(baseTimeInSeconds + 1);
});
const idleSpan = startIdleSpan({ name: 'idle span 2', startTime: baseTimeInSeconds }, { beforeSpanEnd });
const idleSpan = startIdleSpan({ name: 'idle span', startTime: baseTimeInSeconds }, { beforeSpanEnd });
expect(idleSpan).toBeDefined();

expect(beforeSpanEnd).not.toHaveBeenCalled();
Expand All @@ -141,6 +141,10 @@ describe('startIdleSpan', () => {
expect(beforeSendTransaction).toHaveBeenCalledTimes(1);
const transaction = transactions[0];

expect(transaction.start_timestamp).toBe(baseTimeInSeconds);
// It considers the end time of the span we added in beforeSpanEnd
expect(transaction.timestamp).toBe(baseTimeInSeconds + 1);

expect(transaction.contexts?.trace?.data).toEqual(
expect.objectContaining({
foo: 'bar',
Expand Down Expand Up @@ -178,9 +182,9 @@ describe('startIdleSpan', () => {
});

// discardedSpan - startTimestamp is too large
const discardedSpan = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 99 });
const discardedSpan = startInactiveSpan({ name: 'discarded span 1', startTime: baseTimeInSeconds + 99 });
// discardedSpan2 - endTime is too large
const discardedSpan2 = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 3 });
const discardedSpan2 = startInactiveSpan({ name: 'discarded span 2', startTime: baseTimeInSeconds + 3 });
discardedSpan2.end(baseTimeInSeconds + 99)!;

// Should be cancelled - will not finish
Expand Down
Loading