diff --git a/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/init.js b/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/init.js new file mode 100644 index 000000000000..bb6d4918d1bf --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/init.js @@ -0,0 +1,10 @@ +import * as Sentry from '@sentry/browser'; + +window.Sentry = Sentry; + +Sentry.init({ + traceLifecycle: 'static', + dsn: 'https://public@dsn.ingest.sentry.io/1337', + integrations: [Sentry.browserTracingIntegration()], + tracesSampleRate: 1, +}); diff --git a/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/test.ts b/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/test.ts new file mode 100644 index 000000000000..8477d838a613 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/tracing/errorSpanAttribution/test.ts @@ -0,0 +1,103 @@ +import type { Page } from '@playwright/test'; +import { expect } from '@playwright/test'; +import type { Event } from '@sentry/core'; +import { sentryTest } from '../../../utils/fixtures'; +import { + envelopeRequestParser, + runScriptInSandbox, + shouldSkipTracingTest, + waitForErrorRequest, + waitForTransactionRequest, +} from '../../../utils/helpers'; + +// The browser SDK parents every span to the root span, so `outer` and `inner` are siblings under the +// pageload span rather than a chain. Attribution still has to pick the span the error escaped. +const waitForPageloadWithSpans = (page: Page) => + waitForTransactionRequest( + page, + event => event.contexts?.trace?.op === 'pageload' && !!event.spans?.some(span => span.description === 'inner'), + ); + +sentryTest( + 'attributes an uncaught error to the span it escaped, not the pageload span active when it surfaces', + async ({ getLocalTestUrl, page, browserName }) => { + if (browserName === 'webkit') { + // Errors thrown from `runScriptInSandbox` are Script Errors on Webkit and skipped by Sentry + sentryTest.skip(); + } + + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const errorRequestPromise = waitForErrorRequest(page); + const transactionRequestPromise = waitForPageloadWithSpans(page); + + await page.goto(url); + + await runScriptInSandbox(page, { + content: ` + setTimeout(() => { + Sentry.startSpan({ name: 'outer' }, () => { + Sentry.startSpan({ name: 'inner' }, () => { + throw new Error('Escaped Error'); + }); + }); + }); + `, + }); + + const errorEvent = envelopeRequestParser(await errorRequestPromise); + const transactionEvent = envelopeRequestParser(await transactionRequestPromise); + + const innerSpan = transactionEvent.spans?.find(span => span.description === 'inner'); + + expect(errorEvent.exception?.values?.[0]?.value).toBe('Escaped Error'); + expect(errorEvent.contexts?.trace?.trace_id).toBe(transactionEvent.contexts?.trace?.trace_id); + expect(errorEvent.contexts?.trace?.span_id).toBe(innerSpan?.span_id); + expect(errorEvent.contexts?.trace?.span_id).not.toBe(transactionEvent.contexts?.trace?.span_id); + }, +); + +sentryTest( + 'attributes a caught error to the span it escaped, not the span it was caught in', + async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const errorRequestPromise = waitForErrorRequest(page); + const transactionRequestPromise = waitForPageloadWithSpans(page); + + await page.goto(url); + + await runScriptInSandbox(page, { + content: ` + Sentry.startSpan({ name: 'outer' }, () => { + try { + Sentry.startSpan({ name: 'inner' }, () => { + throw new Error('Caught Error'); + }); + } catch (error) { + Sentry.captureException(error); + } + }); + `, + }); + + const errorEvent = envelopeRequestParser(await errorRequestPromise); + const transactionEvent = envelopeRequestParser(await transactionRequestPromise); + + const innerSpan = transactionEvent.spans?.find(span => span.description === 'inner'); + const outerSpan = transactionEvent.spans?.find(span => span.description === 'outer'); + + expect(errorEvent.exception?.values?.[0]?.value).toBe('Caught Error'); + expect(errorEvent.contexts?.trace?.trace_id).toBe(transactionEvent.contexts?.trace?.trace_id); + expect(errorEvent.contexts?.trace?.span_id).toBe(innerSpan?.span_id); + expect(errorEvent.contexts?.trace?.span_id).not.toBe(outerSpan?.span_id); + }, +); diff --git a/dev-packages/e2e-tests/test-applications/node-hapi/tests/errors.test.ts b/dev-packages/e2e-tests/test-applications/node-hapi/tests/errors.test.ts index f355f253b53e..f1f2aaf8aafb 100644 --- a/dev-packages/e2e-tests/test-applications/node-hapi/tests/errors.test.ts +++ b/dev-packages/e2e-tests/test-applications/node-hapi/tests/errors.test.ts @@ -1,23 +1,26 @@ import { expect, test } from '@playwright/test'; -import { waitForError, waitForStreamedSpan } from '@sentry-internal/test-utils'; +import { + collectStreamedSpansUntilSegment, + getSpanOp, + waitForError, + waitForStreamedSpan, +} from '@sentry-internal/test-utils'; test('Sends thrown error to Sentry', async ({ baseURL }) => { const errorEventPromise = waitForError('node-hapi', errorEvent => { return errorEvent?.exception?.values?.[0]?.value === 'This is an error'; }); - const segmentEventPromise = waitForStreamedSpan( - 'node-hapi', - segment => segment.is_segment && segment.name === 'GET /test-failure', - ); + const spansPromise = collectStreamedSpansUntilSegment('node-hapi', 'GET /test-failure'); await fetch(`${baseURL}/test-failure`); const errorEvent = await errorEventPromise; - const segmentEvent = await segmentEventPromise; + const spans = await spansPromise; + const segmentSpan = spans.find(span => span.is_segment); - expect(segmentEvent.name).toBe('GET /test-failure'); - expect(segmentEvent).toMatchObject({ + expect(segmentSpan?.name).toBe('GET /test-failure'); + expect(segmentSpan).toMatchObject({ trace_id: expect.stringMatching(/[a-f0-9]{32}/), span_id: expect.stringMatching(/[a-f0-9]{16}/), }); @@ -42,10 +45,15 @@ test('Sends thrown error to Sentry', async ({ baseURL }) => { expect(errorEvent.contexts?.trace).toEqual({ trace_id: expect.stringMatching(/[a-f0-9]{32}/), span_id: expect.stringMatching(/[a-f0-9]{16}/), + parent_span_id: expect.stringMatching(/[a-f0-9]{16}/), }); - expect(errorEvent.contexts?.trace?.trace_id).toBe(segmentEvent?.trace_id); - expect(errorEvent.contexts?.trace?.span_id).toBe(segmentEvent?.span_id); + // The error is attributed to the route handler span that threw, which is a child of the request + // span the segment is built from. + const routeHandlerSpan = spans.find(span => getSpanOp(span) === 'router'); + expect(errorEvent.contexts?.trace?.trace_id).toBe(segmentSpan?.trace_id); + expect(errorEvent.contexts?.trace?.span_id).toBe(routeHandlerSpan?.span_id); + expect(errorEvent.contexts?.trace?.parent_span_id).toBe(segmentSpan?.span_id); }); test('sends error with parameterized transaction name', async ({ baseURL }) => { diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index fdfaf51d4057..1aa3818a9f1c 100644 --- a/packages/core/src/tracing/trace.ts +++ b/packages/core/src/tracing/trace.ts @@ -14,6 +14,7 @@ import type { StartSpanOptions } from '../types/startSpanOptions'; import { baggageHeaderToDynamicSamplingContext } from '../utils/baggage'; import { debug } from '../utils/debug-logger'; import { handleCallbackErrors } from '../utils/handleCallbackErrors'; +import { recordEscapedErrorSpan } from '../utils/errorSpanAttribution'; import { hasSpansEnabled } from '../utils/hasSpansEnabled'; import { shouldIgnoreSpan } from '../utils/should-ignore-span'; import { hasSpanStreamingEnabled } from './spans/hasSpanStreamingEnabled'; @@ -670,7 +671,9 @@ function runCallback(span: Span, makeSpanActive: boolean, callback: () => T, return wrapper(() => handleCallbackErrors( () => callback(), - () => { + error => { + recordEscapedErrorSpan(error, span); + // Only update the span status if it hasn't been changed yet, and the span is not yet finished const { status } = spanToStaticSpanJSON(span); if (span.isRecording() && status === 'ok') { diff --git a/packages/core/src/utils/errorSpanAttribution.ts b/packages/core/src/utils/errorSpanAttribution.ts new file mode 100644 index 000000000000..729a9bf0c1c6 --- /dev/null +++ b/packages/core/src/utils/errorSpanAttribution.ts @@ -0,0 +1,78 @@ +import { getTraceContextFromScope } from '../currentScopes'; +import type { Scope } from '../scope'; +import type { TraceContext } from '../types/context'; +import type { Event, EventHint } from '../types/event'; +import type { Span } from '../types/span'; +import { isPrimitive } from './is'; +import { spanIsSampled, spanToTraceContext } from './spanUtils'; + +/** + * The trace context of the span an error escaped, keyed by the error itself. + * + * We store the trace context rather than the span because that is the shape we apply to the event + * later, and it snapshots the span as it failed instead of reading it back once it has ended. + */ +const escapedSpanTraceContexts = new WeakMap(); + +/** + * A `WeakMap` can only be keyed by an object, so an error thrown as a primitive (`throw 'boom'`) + * has nothing we can hang the span on and is left unattributed. + */ +function toWeakMapKey(error: unknown): object | undefined { + return isPrimitive(error) ? undefined : error; +} + +/** + * Remember which span an error escaped, so a later `captureException` can attribute the error to + * the span that actually failed instead of whichever span happens to be active at capture time. + * + * The first span to see the error wins: as an error unwinds through nested spans, the innermost + * one is the one that failed. Unsampled spans are skipped because they are never sent, so their + * span id would point at a span that does not exist. Sampling rather than `isRecording()` is what + * matters here: a span ended before the error escaped it, which is the norm for `startSpanManual`, + * has stopped recording but is still sent. + */ +export function recordEscapedErrorSpan(error: unknown, span: Span): void { + const key = toWeakMapKey(error); + + if (!key || !spanIsSampled(span) || escapedSpanTraceContexts.has(key)) { + return; + } + + escapedSpanTraceContexts.set(key, spanToTraceContext(span)); +} + +/** + * Attribute an error event to the span the error escaped, if we recorded one. + * + * This only applies within the error's own trace. The stored span id is meaningless in another + * trace, and the event's dynamic sampling context (which the envelope header is built from) is + * derived from the root span of the trace the event is already on. Rewriting the trace id here + * would leave the envelope header and body naming different traces. + */ +export function applyEscapedErrorSpanToEvent(event: Event, hint: EventHint, scope: Scope | undefined): void { + const key = toWeakMapKey(hint.originalException); + const traceContext = key && escapedSpanTraceContexts.get(key); + + if (!traceContext) { + return; + } + + // An error captured with no active span has no trace context yet: the scope's is merged in + // further downstream. Resolve the trace the event will end up on the same way that merge does, + // so the check below still knows which trace we are on. + const eventTraceContext = event.contexts?.trace; + const eventTraceId = eventTraceContext?.trace_id ?? (scope && getTraceContextFromScope(scope).trace_id); + + if (eventTraceId !== traceContext.trace_id) { + return; + } + + event.contexts = { + ...event.contexts, + trace: { + ...eventTraceContext, + ...traceContext, + }, + }; +} diff --git a/packages/core/src/utils/prepareEvent.ts b/packages/core/src/utils/prepareEvent.ts index 080f1ab752d1..f00e90932135 100644 --- a/packages/core/src/utils/prepareEvent.ts +++ b/packages/core/src/utils/prepareEvent.ts @@ -8,6 +8,7 @@ import type { ClientOptions } from '../types/options'; import type { StackParser } from '../types/stacktrace'; import { getFilenameToDebugIdMap } from './debug-ids'; import { getDataCategoryByType } from './envelope'; +import { applyEscapedErrorSpanToEvent } from './errorSpanAttribution'; import { addExceptionMechanismToCapturedException, uuid4 } from './misc'; import { normalize } from './normalize'; import { applyScopeDataToEvent, applySpanToEvent, getCombinedScopeData } from './scopeData'; @@ -95,6 +96,11 @@ export function prepareEvent( applySpanToEvent(prepared, span); } + // After the active span, so an error that escaped a span is attributed to that span rather than + // to whichever one happened to be active at capture time. Done here rather than once the event is + // assembled so that event processors and the `postprocessEvent` hook see the corrected span id. + applyEscapedErrorSpanToEvent(prepared, hint, finalScope); + const eventProcessors = [ ...clientEventProcessors, // Run scope event processors _after_ all other processors diff --git a/packages/core/test/lib/tracing/errorSpanAttribution.test.ts b/packages/core/test/lib/tracing/errorSpanAttribution.test.ts new file mode 100644 index 000000000000..600ba9d118a5 --- /dev/null +++ b/packages/core/test/lib/tracing/errorSpanAttribution.test.ts @@ -0,0 +1,327 @@ +import { beforeEach, describe, expect, it } from 'vitest'; +import { + addEventProcessor, + captureException, + getActiveSpan, + setAsyncContextStrategy, + setCurrentClient, + startNewTrace, + startSpan, + startSpanManual, +} from '../../../src'; +import type { Event } from '../../../src/types/event'; +import type { TestClientOptions } from '../../mocks/client'; +import { getDefaultTestClientOptions, TestClient } from '../../mocks/client'; +import { resetGlobals } from '../../testutils'; + +const tick = (): Promise => new Promise(resolve => setTimeout(resolve, 0)); + +let client: TestClient; +let events: Event[]; + +function initClient(extraOptions: Partial = {}): void { + events = []; + + const options = getDefaultTestClientOptions({ + tracesSampleRate: 1, + beforeSend: event => { + // The test client strips `sdkProcessingMetadata` when it sends, so snapshot the event here. + events.push({ ...event }); + return event; + }, + ...extraOptions, + }); + client = new TestClient(options); + setCurrentClient(client); + client.init(); +} + +describe('error span attribution', () => { + beforeEach(() => { + resetGlobals(); + setAsyncContextStrategy(undefined); + initClient(); + }); + + it('attributes an error to the span it escaped, not the span it was caught in', async () => { + let innerSpanId: string | undefined; + let outerSpanId: string | undefined; + + startSpan({ name: 'outer' }, outerSpan => { + outerSpanId = outerSpan.spanContext().spanId; + + try { + startSpan({ name: 'inner' }, innerSpan => { + innerSpanId = innerSpan.spanContext().spanId; + throw new Error('inner failed'); + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(innerSpanId).not.toBe(outerSpanId); + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(innerSpanId); + }); + + it('attributes an error to the failing branch of a concurrent group', async () => { + let failingSpanId: string | undefined; + let succeedingSpanId: string | undefined; + let reportingSpanId: string | undefined; + + await startSpan({ name: 'root' }, async () => { + let escapedError: unknown; + + try { + await Promise.all([ + startSpan({ name: 'failing' }, async span => { + failingSpanId = span.spanContext().spanId; + await tick(); + throw new Error('branch failed'); + }), + startSpan({ name: 'succeeding' }, async span => { + succeedingSpanId = span.spanContext().spanId; + await tick(); + }), + ]); + } catch (error) { + escapedError = error; + } + + // Report from a span that is unambiguously active, so the assertion does not depend on + // which scope the stack strategy happens to leak once the branches resume. + startSpan({ name: 'reporting' }, span => { + reportingSpanId = span.spanContext().spanId; + captureException(escapedError); + }); + }); + + await client.flush(); + + expect(failingSpanId).not.toBe(succeedingSpanId); + expect(failingSpanId).not.toBe(reportingSpanId); + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(failingSpanId); + }); + + it('attributes an error captured with no active span, in the same trace', async () => { + let escapedError: unknown; + let escapedSpanId: string | undefined; + + try { + startSpan({ name: 'failing' }, span => { + escapedSpanId = span.spanContext().spanId; + throw new Error('boom'); + }); + } catch (error) { + escapedError = error; + } + + expect(getActiveSpan()).toBeUndefined(); + captureException(escapedError); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(escapedSpanId); + }); + + it('attributes an error to the deepest span it escaped', async () => { + let deepestSpanId: string | undefined; + + startSpan({ name: 'level-1' }, () => { + try { + startSpan({ name: 'level-2' }, () => { + startSpan({ name: 'level-3' }, span => { + deepestSpanId = span.spanContext().spanId; + throw new Error('level 3 failed'); + }); + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(deepestSpanId); + }); + + // The stored span id is only meaningful inside its own trace, so an error that outlives its + // trace keeps today's behaviour rather than mixing a stale trace into the current scope's data. + it('does not attribute an error to a span from a previous trace', async () => { + let escapedError: unknown; + let currentTraceId: string | undefined; + let currentSpanId: string | undefined; + + try { + startSpan({ name: 'previous-trace' }, () => { + throw new Error('escaped its trace'); + }); + } catch (error) { + escapedError = error; + } + + startNewTrace(() => { + startSpan({ name: 'current-trace' }, span => { + currentTraceId = span.spanContext().traceId; + currentSpanId = span.spanContext().spanId; + captureException(escapedError); + }); + }); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.trace_id).toBe(currentTraceId); + expect(events[0]?.contexts?.trace?.span_id).toBe(currentSpanId); + }); + + it('falls back to the active span when a non-object is thrown', async () => { + let outerSpanId: string | undefined; + + startSpan({ name: 'outer' }, outerSpan => { + outerSpanId = outerSpan.spanContext().spanId; + + try { + startSpan({ name: 'inner' }, () => { + throw 'a string, which cannot key a WeakMap'; + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(outerSpanId); + }); + + it('does not attribute an error to an ignored span, which is never sent', async () => { + initClient({ traceLifecycle: 'stream', ignoreSpans: ['ignored'] }); + + let outerSpanId: string | undefined; + + startSpan({ name: 'outer' }, outerSpan => { + outerSpanId = outerSpan.spanContext().spanId; + + try { + startSpan({ name: 'ignored' }, () => { + throw new Error('ignored span failed'); + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(outerSpanId); + }); + + // Why the attribution is gated on the trace: the envelope header is built from the dynamic + // sampling context, so it must never name a different trace than the trace context does. + it('keeps the dynamic sampling context in agreement with the trace context', async () => { + startSpan({ name: 'outer' }, () => { + try { + startSpan({ name: 'inner' }, () => { + throw new Error('inner failed'); + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + const traceContext = events[0]?.contexts?.trace; + expect(traceContext?.trace_id).toBeDefined(); + expect(events[0]?.sdkProcessingMetadata?.dynamicSamplingContext?.trace_id).toBe(traceContext?.trace_id); + }); + // Attribution used to happen once the event was fully assembled, which left event processors + // looking at the span that was active at capture time. + it('has attributed the error before event processors run', async () => { + let seenSpanId: string | undefined; + let innerSpanId: string | undefined; + + addEventProcessor(event => { + if (!event.type) { + seenSpanId = event.contexts?.trace?.span_id; + } + return event; + }); + + startSpan({ name: 'outer' }, () => { + try { + startSpan({ name: 'inner' }, innerSpan => { + innerSpanId = innerSpan.spanContext().spanId; + throw new Error('inner failed'); + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(seenSpanId).toBe(innerSpanId); + }); + + it('leaves the event with a complete trace context when nothing is active at capture time', async () => { + let innerSpanId: string | undefined; + let traceId: string | undefined; + let caught: unknown; + + startSpan({ name: 'outer' }, outerSpan => { + traceId = outerSpan.spanContext().traceId; + + try { + startSpan({ name: 'inner' }, innerSpan => { + innerSpanId = innerSpan.spanContext().spanId; + throw new Error('inner failed'); + }); + } catch (error) { + caught = error; + } + }); + + expect(getActiveSpan()).toBeUndefined(); + captureException(caught); + + await client.flush(); + + expect(events[0]?.contexts?.trace).toEqual(expect.objectContaining({ trace_id: traceId, span_id: innerSpanId })); + }); + // `startSpanManual` ends the span inside the callback, so by the time the error unwinds past it + // the span has stopped recording. It is still sampled and still sent, so it is still the span + // the error escaped. + it('attributes an error to a span that was ended before the error escaped it', async () => { + let innerSpanId: string | undefined; + + startSpan({ name: 'outer' }, () => { + try { + startSpanManual({ name: 'inner' }, span => { + innerSpanId = span.spanContext().spanId; + try { + throw new Error('inner failed'); + } finally { + span.end(); + } + }); + } catch (error) { + captureException(error); + } + }); + + await client.flush(); + + expect(events).toHaveLength(1); + expect(events[0]?.contexts?.trace?.span_id).toBe(innerSpanId); + }); +});