From fd5417aa92178c255bea8dc2183854c6130fcf3a Mon Sep 17 00:00:00 2001 From: Luca Forstner Date: Tue, 30 Jan 2024 12:19:11 +0100 Subject: [PATCH 1/2] fix: Fork scope and keep async context within `startSpan` and `startSpanManual` --- packages/core/src/tracing/trace.ts | 96 ++++++++-------- packages/node/test/performance.test.ts | 150 +++++++++++++++++++++++++ 2 files changed, 200 insertions(+), 46 deletions(-) create mode 100644 packages/node/test/performance.test.ts diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index bdeba55ed9e4..e9f05a00bb94 100644 --- a/packages/core/src/tracing/trace.ts +++ b/packages/core/src/tracing/trace.ts @@ -4,7 +4,7 @@ import { dropUndefinedKeys, logger, tracingContextFromHeaders } from '@sentry/ut import { DEBUG_BUILD } from '../debug-build'; import { getCurrentScope, withScope } from '../exports'; -import type { Hub } from '../hub'; +import { Hub, runWithAsyncContext } from '../hub'; import { getIsolationScope } from '../hub'; import { getCurrentHub } from '../hub'; import { handleCallbackErrors } from '../utils/handleCallbackErrors'; @@ -74,29 +74,31 @@ export function trace( export function startSpan(context: StartSpanOptions, callback: (span: Span | undefined) => T): T { const ctx = normalizeContext(context); - return withScope(context.scope, scope => { - // eslint-disable-next-line deprecation/deprecation - const hub = getCurrentHub(); - // eslint-disable-next-line deprecation/deprecation - const parentSpan = scope.getSpan(); + return runWithAsyncContext(() => { + return withScope(context.scope, scope => { + // eslint-disable-next-line deprecation/deprecation + const hub = getCurrentHub(); + // eslint-disable-next-line deprecation/deprecation + const parentSpan = scope.getSpan(); - const activeSpan = createChildSpanOrTransaction(hub, parentSpan, ctx); - // eslint-disable-next-line deprecation/deprecation - scope.setSpan(activeSpan); - - return handleCallbackErrors( - () => callback(activeSpan), - () => { - // Only update the span status if it hasn't been changed yet - if (activeSpan) { - const { status } = spanToJSON(activeSpan); - if (!status || status === 'ok') { - activeSpan.setStatus('internal_error'); + const activeSpan = createChildSpanOrTransaction(hub, parentSpan, ctx); + // eslint-disable-next-line deprecation/deprecation + scope.setSpan(activeSpan); + + return handleCallbackErrors( + () => callback(activeSpan), + () => { + // Only update the span status if it hasn't been changed yet + if (activeSpan) { + const { status } = spanToJSON(activeSpan); + if (!status || status === 'ok') { + activeSpan.setStatus('internal_error'); + } } - } - }, - () => activeSpan && activeSpan.end(), - ); + }, + () => activeSpan && activeSpan.end(), + ); + }); }); } @@ -122,32 +124,34 @@ export function startSpanManual( ): T { const ctx = normalizeContext(context); - return withScope(context.scope, scope => { - // eslint-disable-next-line deprecation/deprecation - const hub = getCurrentHub(); - // eslint-disable-next-line deprecation/deprecation - const parentSpan = scope.getSpan(); - - const activeSpan = createChildSpanOrTransaction(hub, parentSpan, ctx); - // eslint-disable-next-line deprecation/deprecation - scope.setSpan(activeSpan); + return runWithAsyncContext(() => { + return withScope(context.scope, scope => { + // eslint-disable-next-line deprecation/deprecation + const hub = getCurrentHub(); + // eslint-disable-next-line deprecation/deprecation + const parentSpan = scope.getSpan(); - function finishAndSetSpan(): void { - activeSpan && activeSpan.end(); - } - - return handleCallbackErrors( - () => callback(activeSpan, finishAndSetSpan), - () => { - // Only update the span status if it hasn't been changed yet, and the span is not yet finished - if (activeSpan && activeSpan.isRecording()) { - const { status } = spanToJSON(activeSpan); - if (!status || status === 'ok') { - activeSpan.setStatus('internal_error'); + const activeSpan = createChildSpanOrTransaction(hub, parentSpan, ctx); + // eslint-disable-next-line deprecation/deprecation + scope.setSpan(activeSpan); + + function finishAndSetSpan(): void { + activeSpan && activeSpan.end(); + } + + return handleCallbackErrors( + () => callback(activeSpan, finishAndSetSpan), + () => { + // Only update the span status if it hasn't been changed yet, and the span is not yet finished + if (activeSpan && activeSpan.isRecording()) { + const { status } = spanToJSON(activeSpan); + if (!status || status === 'ok') { + activeSpan.setStatus('internal_error'); + } } - } - }, - ); + }, + ); + }); }); } diff --git a/packages/node/test/performance.test.ts b/packages/node/test/performance.test.ts new file mode 100644 index 000000000000..0f57dd4166e6 --- /dev/null +++ b/packages/node/test/performance.test.ts @@ -0,0 +1,150 @@ +import { setAsyncContextStrategy, setCurrentClient, startSpan, startSpanManual } from '@sentry/core'; +import type { TransactionEvent } from '@sentry/types'; +import { NodeClient, defaultStackParser } from '../src'; +import { setNodeAsyncContextStrategy } from '../src/async'; +import { getDefaultNodeClientOptions } from './helper/node-client-options'; + +const dsn = 'https://53039209a22b4ec1bcc296a3c9fdecd6@sentry.io/4291'; + +beforeAll(() => { + setNodeAsyncContextStrategy(); +}); + +afterAll(() => { + setAsyncContextStrategy(undefined); +}); + +describe('startSpan()', () => { + it('should correctly separate spans when called after one another with interwoven timings', async () => { + const transactionEventPromise = new Promise(resolve => { + setCurrentClient( + new NodeClient( + getDefaultNodeClientOptions({ + stackParser: defaultStackParser, + tracesSampleRate: 1, + beforeSendTransaction: event => { + resolve(event); + return null; + }, + dsn, + }), + ), + ); + }); + + startSpan({ name: 'first' }, () => { + return new Promise(resolve => { + setTimeout(resolve, 500); + }); + }); + + startSpan({ name: 'second' }, () => { + return new Promise(resolve => { + setTimeout(resolve, 250); + }); + }); + + const transactionEvent = await transactionEventPromise; + + // Any transaction events happening shouldn't have any child spans + expect(transactionEvent.spans).toStrictEqual([]); + }); + + it('should correctly nest spans when called within one another', async () => { + const transactionEventPromise = new Promise(resolve => { + setCurrentClient( + new NodeClient( + getDefaultNodeClientOptions({ + stackParser: defaultStackParser, + tracesSampleRate: 1, + beforeSendTransaction: event => { + resolve(event); + return null; + }, + dsn, + }), + ), + ); + }); + + startSpan({ name: 'first' }, () => { + startSpan({ name: 'second' }, () => undefined); + }); + + const transactionEvent = await transactionEventPromise; + + expect(transactionEvent.spans).toContainEqual(expect.objectContaining({ description: 'second' })); + }); +}); + +describe('startSpanManual()', () => { + it('should correctly separate spans when called after one another with interwoven timings', async () => { + const transactionEventPromise = new Promise(resolve => { + setCurrentClient( + new NodeClient( + getDefaultNodeClientOptions({ + stackParser: defaultStackParser, + tracesSampleRate: 1, + beforeSendTransaction: event => { + resolve(event); + return null; + }, + dsn, + }), + ), + ); + }); + + startSpanManual({ name: 'first' }, span => { + return new Promise(resolve => { + setTimeout(() => { + span?.end(); + resolve(); + }, 500); + }); + }); + + startSpanManual({ name: 'second' }, span => { + return new Promise(resolve => { + setTimeout(() => { + span?.end(); + resolve(); + }, 500); + }); + }); + + const transactionEvent = await transactionEventPromise; + + // Any transaction events happening shouldn't have any child spans + expect(transactionEvent.spans).toStrictEqual([]); + }); + + it('should correctly nest spans when called within one another', async () => { + const transactionEventPromise = new Promise(resolve => { + setCurrentClient( + new NodeClient( + getDefaultNodeClientOptions({ + stackParser: defaultStackParser, + tracesSampleRate: 1, + beforeSendTransaction: event => { + resolve(event); + return null; + }, + dsn, + }), + ), + ); + }); + + startSpanManual({ name: 'first' }, span1 => { + startSpanManual({ name: 'second' }, span2 => { + span2?.end(); + }); + span1?.end(); + }); + + const transactionEvent = await transactionEventPromise; + + expect(transactionEvent.spans).toContainEqual(expect.objectContaining({ description: 'second' })); + }); +}); From 06eafc1f785c211ab9b4fb38a7d59622fe935c76 Mon Sep 17 00:00:00 2001 From: Luca Forstner Date: Tue, 30 Jan 2024 12:39:54 +0100 Subject: [PATCH 2/2] Lint --- packages/core/src/tracing/trace.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index 69adcc2076df..dc822a2bab7d 100644 --- a/packages/core/src/tracing/trace.ts +++ b/packages/core/src/tracing/trace.ts @@ -4,7 +4,8 @@ import { dropUndefinedKeys, logger, tracingContextFromHeaders } from '@sentry/ut import { DEBUG_BUILD } from '../debug-build'; import { getCurrentScope, withScope } from '../exports'; -import { Hub, runWithAsyncContext } from '../hub'; +import type { Hub } from '../hub'; +import { runWithAsyncContext } from '../hub'; import { getIsolationScope } from '../hub'; import { getCurrentHub } from '../hub'; import { handleCallbackErrors } from '../utils/handleCallbackErrors';