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 39edc8bcde0e..a41fdd72091c 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 @@ -41,10 +41,16 @@ 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}/), }); + // The error is attributed to the route handler span that threw, which is a child of the request + // span the transaction is built from. expect(errorEvent.contexts?.trace?.trace_id).toBe(transactionEvent.contexts?.trace?.trace_id); - expect(errorEvent.contexts?.trace?.span_id).toBe(transactionEvent.contexts?.trace?.span_id); + expect(errorEvent.contexts?.trace?.parent_span_id).toBe(transactionEvent.contexts?.trace?.span_id); + + const blamedSpan = transactionEvent.spans?.find(span => span.span_id === errorEvent.contexts?.trace?.span_id); + expect(blamedSpan?.op).toBe('router'); }); test('sends error with parameterized transaction name', async ({ baseURL }) => { diff --git a/packages/core/src/client.ts b/packages/core/src/client.ts index 5a14b13c07fa..cdf84ac9b138 100644 --- a/packages/core/src/client.ts +++ b/packages/core/src/client.ts @@ -4,6 +4,7 @@ import { DEFAULT_ENVIRONMENT } from './constants'; import { getCurrentScope, getIsolationScope, getTraceContextFromScope } from './currentScopes'; import { DEBUG_BUILD } from './debug-build'; import { createEventEnvelope, createSessionEnvelope } from './envelope'; +import { applyEscapedErrorSpanToEvent } from './utils/errorSpanAttribution'; import type { IntegrationIndex } from './integration'; import { afterSetupIntegrations, setupIntegration, setupIntegrations } from './integration'; import { _INTERNAL_flushLogsBuffer } from './logs/internal'; @@ -1442,6 +1443,11 @@ export abstract class Client { ...evt.contexts, }; + // Deliberately after the merge above: an error captured with no active span has no trace + // context until then, and without its trace id we cannot tell whether the span we recorded + // belongs to the same trace, which risks the event disagreeing with the DSC we build below. + applyEscapedErrorSpanToEvent(evt, hint); + const dynamicSamplingContext = getDynamicSamplingContextFromScope(this, currentScope); evt.sdkProcessingMetadata = { diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index b52d62624f23..b6773f9f9cb6 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'; @@ -667,7 +668,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..c3015cc660cd --- /dev/null +++ b/packages/core/src/utils/errorSpanAttribution.ts @@ -0,0 +1,66 @@ +import type { TraceContext } from '../types/context'; +import type { Event, EventHint } from '../types/event'; +import type { Span } from '../types/span'; +import { isPrimitive } from './is'; +import { 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. Non-recording spans are skipped because they are never sent, so + * their span id would point at a span that does not exist. + */ +export function recordEscapedErrorSpan(error: unknown, span: Span): void { + const key = toWeakMapKey(error); + + if (!key || !span.isRecording() || 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): void { + const key = toWeakMapKey(hint.originalException); + const traceContext = key && escapedSpanTraceContexts.get(key); + const eventTraceContext = event.contexts?.trace; + + if (!traceContext || !eventTraceContext || eventTraceContext.trace_id !== traceContext.trace_id) { + return; + } + + event.contexts = { + ...event.contexts, + trace: { + ...eventTraceContext, + span_id: traceContext.span_id, + parent_span_id: traceContext.parent_span_id, + }, + }; +} 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..0b3ea97d0cd5 --- /dev/null +++ b/packages/core/test/lib/tracing/errorSpanAttribution.test.ts @@ -0,0 +1,245 @@ +import { beforeEach, describe, expect, it } from 'vitest'; +import { + captureException, + getActiveSpan, + setAsyncContextStrategy, + setCurrentClient, + startNewTrace, + startSpan, +} 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); + }); +});