From cf412d9373960ddddf5eb7723c1cff7906b22488 Mon Sep 17 00:00:00 2001 From: Lukas Stracke Date: Fri, 22 Dec 2023 11:23:49 +0100 Subject: [PATCH] fix(core): Rethrow caught promise rejections in `startSpan`, `startSpanManual`, `trace` (#9958) Our previous implementation of `startSpan` et.al. assumed that because we were "cloning" the original promise, unhandled promise rejections would still bubble up to the global `onunhandledrejection` handler so that Sentry would catch the error. However, we tried investigating this and found out that our "cloning" mechanism didn't work correctly and because we already added a rejection handler, the promise rejection would _not always_ make it to the global handler. After adding multiple integration tests, I further narrowed the buggy behaviour down to a rather special case: The `startSpan` call is not `await`ed which for some reason will lead to the SDK not catching the error. Unless, we apply the fix in this PR. This patch removes this cloning mechanism in favour of directly attaching a rejection handler to the promise. In this handler, we rethrow the error which should trigger the global handlers. --- .../public-api/startSpan/basic/subject.js | 9 +++++ .../suites/public-api/startSpan/basic/test.ts | 34 ++++++++++++++++++ .../error-async-reject/template.html | 23 ++++++++++++ .../startSpan/error-async-reject/test.ts | 31 ++++++++++++++++ .../template.html | 23 ++++++++++++ .../error-async-throw-not-awaited/test.ts | 28 +++++++++++++++ .../startSpan/error-async-throw/template.html | 24 +++++++++++++ .../startSpan/error-async-throw/test.ts | 25 +++++++++++++ .../startSpan/error-sync/subject.js | 9 +++++ .../public-api/startSpan/error-sync/test.ts | 22 ++++++++++++ .../suites/public-api/startSpan/init.js | 13 +++++++ packages/core/src/tracing/trace.ts | 35 ++++++++++++------- 12 files changed, 263 insertions(+), 13 deletions(-) create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/basic/subject.js create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/basic/test.ts create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/template.html create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/test.ts create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/template.html create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/test.ts create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/template.html create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/test.ts create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-sync/subject.js create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/error-sync/test.ts create mode 100644 packages/browser-integration-tests/suites/public-api/startSpan/init.js diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/basic/subject.js b/packages/browser-integration-tests/suites/public-api/startSpan/basic/subject.js new file mode 100644 index 000000000000..5f4dbea513a8 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/basic/subject.js @@ -0,0 +1,9 @@ +async function run() { + Sentry.startSpan({ name: 'parent_span' }, () => { + Sentry.startSpan({ name: 'child_span' }, () => { + // whatever a user would do here + }); + }); +} + +run(); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/basic/test.ts b/packages/browser-integration-tests/suites/public-api/startSpan/basic/test.ts new file mode 100644 index 000000000000..a4b5d8b9bd02 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/basic/test.ts @@ -0,0 +1,34 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getFirstSentryEnvelopeRequest, shouldSkipTracingTest } from '../../../../utils/helpers'; + +sentryTest('should send a transaction in an envelope', async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestPath({ testDir: __dirname }); + const transaction = await getFirstSentryEnvelopeRequest(page, url); + + expect(transaction.transaction).toBe('parent_span'); + expect(transaction.spans).toBeDefined(); +}); + +sentryTest('should report finished spans as children of the root transaction', async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestPath({ testDir: __dirname }); + const transaction = await getFirstSentryEnvelopeRequest(page, url); + + const rootSpanId = transaction?.contexts?.trace?.spanId; + + expect(transaction.spans).toHaveLength(1); + + const span_1 = transaction.spans?.[0]; + expect(span_1?.description).toBe('child_span'); + expect(span_1?.parentSpanId).toEqual(rootSpanId); +}); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/template.html b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/template.html new file mode 100644 index 000000000000..1a1cec6b25d7 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/template.html @@ -0,0 +1,23 @@ + + + + + + + + + + + + diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/test.ts b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/test.ts new file mode 100644 index 000000000000..e328d4869b24 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-reject/test.ts @@ -0,0 +1,31 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getMultipleSentryEnvelopeRequests, shouldSkipTracingTest } from '../../../../utils/helpers'; + +sentryTest( + 'should capture a promise rejection within an async startSpan callback', + async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestPath({ testDir: __dirname }); + const envelopePromise = getMultipleSentryEnvelopeRequests(page, 2); + + await page.goto(url); + + const clickPromise = page.getByText('Button 1').click(); + + const [, events] = await Promise.all([clickPromise, envelopePromise]); + const txn = events.find(event => event.type === 'transaction'); + const err = events.find(event => !event.type); + + expect(txn).toMatchObject({ transaction: 'parent_span' }); + + expect(err?.exception?.values?.[0]?.value).toBe( + 'Non-Error promise rejection captured with value: Async Promise Rejection', + ); + }, +); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/template.html b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/template.html new file mode 100644 index 000000000000..9f4044dedff1 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/template.html @@ -0,0 +1,23 @@ + + + + + + + + + + + + diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/test.ts b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/test.ts new file mode 100644 index 000000000000..5ef6f22419d1 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw-not-awaited/test.ts @@ -0,0 +1,28 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getMultipleSentryEnvelopeRequests, shouldSkipTracingTest } from '../../../../utils/helpers'; + +sentryTest( + "should capture a thrown error within an async startSpan callback that's not awaited properly", + async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + const envelopePromise = getMultipleSentryEnvelopeRequests(page, 2); + + const url = await getLocalTestPath({ testDir: __dirname }); + await page.goto(url); + + const clickPromise = page.getByText('Button 1').click(); + + // awaiting both events simultaneously to avoid race conditions + const [, events] = await Promise.all([clickPromise, envelopePromise]); + const txn = events.find(event => event.type === 'transaction'); + const err = events.find(event => !event.type); + + expect(txn).toMatchObject({ transaction: 'parent_span' }); + expect(err?.exception?.values?.[0]?.value).toBe('Async Thrown Error'); + }, +); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/template.html b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/template.html new file mode 100644 index 000000000000..e4a96b1f0691 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/template.html @@ -0,0 +1,24 @@ + + + + + + + + + + + + diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/test.ts b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/test.ts new file mode 100644 index 000000000000..15ee3b9bd4de --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-async-throw/test.ts @@ -0,0 +1,25 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getMultipleSentryEnvelopeRequests, shouldSkipTracingTest } from '../../../../utils/helpers'; + +sentryTest('should capture a thrown error within an async startSpan callback', async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + const envelopePromise = getMultipleSentryEnvelopeRequests(page, 2); + + const url = await getLocalTestPath({ testDir: __dirname }); + await page.goto(url); + + const clickPromise = page.getByText('Button 1').click(); + + // awaiting both events simultaneously to avoid race conditions + const [, events] = await Promise.all([clickPromise, envelopePromise]); + const txn = events.find(event => event.type === 'transaction'); + const err = events.find(event => !event.type); + + expect(txn).toMatchObject({ transaction: 'parent_span' }); + expect(err?.exception?.values?.[0]?.value).toBe('Async Thrown Error'); +}); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/subject.js b/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/subject.js new file mode 100644 index 000000000000..55d9bf76d224 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/subject.js @@ -0,0 +1,9 @@ +function run() { + Sentry.startSpan({ name: 'parent_span' }, () => { + throw new Error('Sync Error'); + }); +} + +// using `setTimeout` here because otherwise the thrown error will be +// thrown as a generic "Script Error." instead of the actual error". +setTimeout(run); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/test.ts b/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/test.ts new file mode 100644 index 000000000000..4cba6929396f --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/error-sync/test.ts @@ -0,0 +1,22 @@ +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/types'; + +import { sentryTest } from '../../../../utils/fixtures'; +import { getMultipleSentryEnvelopeRequests, shouldSkipTracingTest } from '../../../../utils/helpers'; + +sentryTest('should capture an error within a sync startSpan callback', async ({ getLocalTestPath, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestPath({ testDir: __dirname }); + const gotoPromise = page.goto(url); + const envelopePromise = getMultipleSentryEnvelopeRequests(page, 2); + + const [_, events] = await Promise.all([gotoPromise, envelopePromise]); + const txn = events.find(event => event.type === 'transaction'); + const err = events.find(event => !event.type); + + expect(txn).toMatchObject({ transaction: 'parent_span' }); + expect(err?.exception?.values?.[0]?.value).toBe('Sync Error'); +}); diff --git a/packages/browser-integration-tests/suites/public-api/startSpan/init.js b/packages/browser-integration-tests/suites/public-api/startSpan/init.js new file mode 100644 index 000000000000..b0bf1e869254 --- /dev/null +++ b/packages/browser-integration-tests/suites/public-api/startSpan/init.js @@ -0,0 +1,13 @@ +/* eslint-disable no-unused-vars */ +import * as Sentry from '@sentry/browser'; +// biome-ignore lint/nursery/noUnusedImports: Need to import tracing for side effect +import * as _ from '@sentry/tracing'; + +window.Sentry = Sentry; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + tracesSampleRate: 1.0, + normalizeDepth: 10, + debug: true, +}); diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index db6e34aa487e..1b01ee20490c 100644 --- a/packages/core/src/tracing/trace.ts +++ b/packages/core/src/tracing/trace.ts @@ -55,23 +55,25 @@ export function trace( } if (isThenable(maybePromiseResult)) { - Promise.resolve(maybePromiseResult).then( - () => { + // @ts-expect-error - the isThenable check returns the "wrong" type here + return maybePromiseResult.then( + res => { finishAndSetSpan(); afterFinish(); + return res; }, e => { activeSpan && activeSpan.setStatus('internal_error'); onError(e, activeSpan); finishAndSetSpan(); afterFinish(); + throw e; }, ); - } else { - finishAndSetSpan(); - afterFinish(); } + finishAndSetSpan(); + afterFinish(); return maybePromiseResult; } @@ -89,6 +91,7 @@ export function trace( export function startSpan(context: TransactionContext, callback: (span: Span | undefined) => T): T { const ctx = normalizeContext(context); + // @ts-expect-error - isThenable returns the wrong type return withScope(scope => { const hub = getCurrentHub(); const parentSpan = scope.getSpan(); @@ -110,19 +113,20 @@ export function startSpan(context: TransactionContext, callback: (span: Span } if (isThenable(maybePromiseResult)) { - Promise.resolve(maybePromiseResult).then( - () => { + return maybePromiseResult.then( + res => { finishAndSetSpan(); + return res; }, - () => { + e => { activeSpan && activeSpan.setStatus('internal_error'); finishAndSetSpan(); + throw e; }, ); - } else { - finishAndSetSpan(); } + finishAndSetSpan(); return maybePromiseResult; }); } @@ -149,6 +153,7 @@ export function startSpanManual( ): T { const ctx = normalizeContext(context); + // @ts-expect-error - isThenable returns the wrong type return withScope(scope => { const hub = getCurrentHub(); const parentSpan = scope.getSpan(); @@ -169,9 +174,13 @@ export function startSpanManual( } if (isThenable(maybePromiseResult)) { - Promise.resolve(maybePromiseResult).then(undefined, () => { - activeSpan && activeSpan.setStatus('internal_error'); - }); + return maybePromiseResult.then( + res => res, + e => { + activeSpan && activeSpan.setStatus('internal_error'); + throw e; + }, + ); } return maybePromiseResult;