From d8d932443cd79ea0438d1646f812a90aa098a23b Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Mon, 25 Nov 2024 09:06:49 +0100 Subject: [PATCH] test: Add tests to demonstrate root trace ID behavior (#14426) This adds node & browser integration tests to demonstrate the current behavior of "trace propagation" based on the current scope. It shows that the behavior is not really consistent and we should probably adjust it, but for now this PR does no changes. ## Browser In browser, the propagation context of the current scope is always picked up. This means that if you call `startSpan` multiple times in the root, both started spans will have the same trace ID, and possibly the same `parentSpanId` if there was an incoming trace. ## Node In node, the propagation context is ignored for the root context. So in the root, started spans will have different traces, and will also ignore parentSpanId (which is only theoretical, there will never really be a parentSpanId on the root scope in node, realistically). Outside of the root (so e.g. within any route handler, or even any `withScope` call), the behavior is the same as in browser - any started spans will share the same trace ID/parent span ID. ## What should we take away from this? In node, I would align the behavior to ignore the trace ID when we have no incoming trace (so no parentSpanId), and always use the traceId & parentSpanId if there is a parentSpanId on the scope (even the root scope, to be consistent). In browser, we cannot make this change because we rely on this behavior for the extended traces after pageload/navigation spans have ended. --- .../parallel-root-spans-in-scope/subject.js | 4 ++ .../parallel-root-spans-in-scope/test.ts | 41 +++++++++++++++++++ .../subject.js | 8 ++++ .../test.ts | 38 +++++++++++++++++ .../startSpan/parallel-root-spans/subject.js | 2 + .../startSpan/parallel-root-spans/test.ts | 38 +++++++++++++++++ .../utils/helpers.ts | 16 +++++++- .../startSpan/parallel-root-spans/scenario.ts | 30 ++++++++++++++ .../startSpan/parallel-root-spans/test.ts | 29 +++++++++++++ .../scenario.ts | 20 +++++++++ .../test.ts | 34 +++++++++++++++ .../parallel-spans-in-scope/scenario.ts | 26 ++++++++++++ .../startSpan/parallel-spans-in-scope/test.ts | 27 ++++++++++++ packages/opentelemetry/src/trace.ts | 3 +- 14 files changed, 313 insertions(+), 3 deletions(-) create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/subject.js create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/test.ts create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/subject.js create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/test.ts create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/subject.js create mode 100644 dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/scenario.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/scenario.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/test.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/scenario.ts create mode 100644 dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/test.ts diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/subject.js b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/subject.js new file mode 100644 index 000000000000..1fa6434c2634 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/subject.js @@ -0,0 +1,4 @@ +Sentry.withScope(() => { + Sentry.startSpan({ name: 'test_span_1' }, () => undefined); + Sentry.startSpan({ name: 'test_span_2' }, () => undefined); +}); diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/test.ts b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/test.ts new file mode 100644 index 000000000000..8ad6e31eccce --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-in-scope/test.ts @@ -0,0 +1,41 @@ +import { expect } from '@playwright/test'; + +import type { TransactionEvent } from '@sentry/types'; +import { sentryTest } from '../../../../utils/fixtures'; +import { envelopeRequestParser, shouldSkipTracingTest, waitForTransactionRequest } from '../../../../utils/helpers'; + +sentryTest( + 'should send manually started parallel root spans outside of root context', + async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const transaction1ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_1'); + const transaction2ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_2'); + + await page.goto(url); + + const [transaction1Req, transaction2Req] = await Promise.all([transaction1ReqPromise, transaction2ReqPromise]); + + const transaction1 = envelopeRequestParser(transaction1Req); + const transaction2 = envelopeRequestParser(transaction2Req); + + expect(transaction1).toBeDefined(); + expect(transaction2).toBeDefined(); + + const trace1Id = transaction1.contexts?.trace?.trace_id; + const trace2Id = transaction2.contexts?.trace?.trace_id; + + expect(trace1Id).toBeDefined(); + expect(trace2Id).toBeDefined(); + + // We use the same traceID from the root propagation context here + expect(trace1Id).toBe(trace2Id); + + expect(transaction1.contexts?.trace?.parent_span_id).toBeUndefined(); + expect(transaction2.contexts?.trace?.parent_span_id).toBeUndefined(); + }, +); diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/subject.js b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/subject.js new file mode 100644 index 000000000000..56c0e05a269c --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/subject.js @@ -0,0 +1,8 @@ +Sentry.getCurrentScope().setPropagationContext({ + parentSpanId: '1234567890123456', + spanId: '123456789012345x', + traceId: '12345678901234567890123456789012', +}); + +Sentry.startSpan({ name: 'test_span_1' }, () => undefined); +Sentry.startSpan({ name: 'test_span_2' }, () => undefined); diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/test.ts b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/test.ts new file mode 100644 index 000000000000..212e4808f3e7 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans-with-parentSpanId/test.ts @@ -0,0 +1,38 @@ +import { expect } from '@playwright/test'; + +import type { TransactionEvent } from '@sentry/types'; +import { sentryTest } from '../../../../utils/fixtures'; +import { envelopeRequestParser, shouldSkipTracingTest, waitForTransactionRequest } from '../../../../utils/helpers'; + +sentryTest( + 'should send manually started parallel root spans in root context with parentSpanId', + async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const transaction1ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_1'); + const transaction2ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_2'); + + await page.goto(url); + + const [transaction1Req, transaction2Req] = await Promise.all([transaction1ReqPromise, transaction2ReqPromise]); + + const transaction1 = envelopeRequestParser(transaction1Req); + const transaction2 = envelopeRequestParser(transaction2Req); + + expect(transaction1).toBeDefined(); + expect(transaction2).toBeDefined(); + + const trace1Id = transaction1.contexts?.trace?.trace_id; + const trace2Id = transaction2.contexts?.trace?.trace_id; + + expect(trace1Id).toBe('12345678901234567890123456789012'); + expect(trace2Id).toBe('12345678901234567890123456789012'); + + expect(transaction1.contexts?.trace?.parent_span_id).toBe('1234567890123456'); + expect(transaction2.contexts?.trace?.parent_span_id).toBe('1234567890123456'); + }, +); diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/subject.js b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/subject.js new file mode 100644 index 000000000000..b07ba4e8aab2 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/subject.js @@ -0,0 +1,2 @@ +Sentry.startSpan({ name: 'test_span_1' }, () => undefined); +Sentry.startSpan({ name: 'test_span_2' }, () => undefined); diff --git a/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts new file mode 100644 index 000000000000..47e8e9fa3ac5 --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts @@ -0,0 +1,38 @@ +import { expect } from '@playwright/test'; + +import type { TransactionEvent } from '@sentry/types'; +import { sentryTest } from '../../../../utils/fixtures'; +import { envelopeRequestParser, shouldSkipTracingTest, waitForTransactionRequest } from '../../../../utils/helpers'; + +sentryTest('should send manually started parallel root spans in root context', async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const transaction1ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_1'); + const transaction2ReqPromise = waitForTransactionRequest(page, event => event.transaction === 'test_span_2'); + + await page.goto(url); + + const [transaction1Req, transaction2Req] = await Promise.all([transaction1ReqPromise, transaction2ReqPromise]); + + const transaction1 = envelopeRequestParser(transaction1Req); + const transaction2 = envelopeRequestParser(transaction2Req); + + expect(transaction1).toBeDefined(); + expect(transaction2).toBeDefined(); + + const trace1Id = transaction1.contexts?.trace?.trace_id; + const trace2Id = transaction2.contexts?.trace?.trace_id; + + expect(trace1Id).toBeDefined(); + expect(trace2Id).toBeDefined(); + + // We use the same traceID from the root propagation context here + expect(trace1Id).toBe(trace2Id); + + expect(transaction1.contexts?.trace?.parent_span_id).toBeUndefined(); + expect(transaction2.contexts?.trace?.parent_span_id).toBeUndefined(); +}); diff --git a/dev-packages/browser-integration-tests/utils/helpers.ts b/dev-packages/browser-integration-tests/utils/helpers.ts index 01d92a07a8e5..34e591cad0dc 100644 --- a/dev-packages/browser-integration-tests/utils/helpers.ts +++ b/dev-packages/browser-integration-tests/utils/helpers.ts @@ -7,6 +7,7 @@ import type { Event, EventEnvelope, EventEnvelopeHeaders, + TransactionEvent, } from '@sentry/types'; export const envelopeUrlRegex = /\.sentry\.io\/api\/\d+\/envelope\//; @@ -224,7 +225,10 @@ export function waitForErrorRequest(page: Page, callback?: (event: Event) => boo }); } -export function waitForTransactionRequest(page: Page): Promise { +export function waitForTransactionRequest( + page: Page, + callback?: (event: TransactionEvent) => boolean, +): Promise { return page.waitForRequest(req => { const postData = req.postData(); if (!postData) { @@ -234,7 +238,15 @@ export function waitForTransactionRequest(page: Page): Promise { try { const event = envelopeRequestParser(req); - return event.type === 'transaction'; + if (event.type !== 'transaction') { + return false; + } + + if (callback) { + return callback(event as TransactionEvent); + } + + return true; } catch { return false; } diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/scenario.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/scenario.ts new file mode 100644 index 000000000000..e352fff5c02c --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/scenario.ts @@ -0,0 +1,30 @@ +import { loggingTransport } from '@sentry-internal/node-integration-tests'; +import * as Sentry from '@sentry/node'; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + release: '1.0', + tracesSampleRate: 1.0, + transport: loggingTransport, +}); + +Sentry.getCurrentScope().setPropagationContext({ + parentSpanId: '1234567890123456', + spanId: '123456789012345x', + traceId: '12345678901234567890123456789012', +}); + +const spanIdTraceId = Sentry.startSpan( + { + name: 'test_span_1', + }, + span1 => span1.spanContext().traceId, +); + +Sentry.startSpan( + { + name: 'test_span_2', + attributes: { spanIdTraceId }, + }, + () => undefined, +); diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts new file mode 100644 index 000000000000..ed7726d72389 --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-root-spans/test.ts @@ -0,0 +1,29 @@ +import { cleanupChildProcesses, createRunner } from '../../../../utils/runner'; + +afterAll(() => { + cleanupChildProcesses(); +}); + +test('should send manually started parallel root spans in root context', done => { + expect.assertions(7); + + createRunner(__dirname, 'scenario.ts') + .expect({ transaction: { transaction: 'test_span_1' } }) + .expect({ + transaction: transaction => { + expect(transaction).toBeDefined(); + const traceId = transaction.contexts?.trace?.trace_id; + expect(traceId).toBeDefined(); + + // It ignores propagation context of the root context + expect(traceId).not.toBe('12345678901234567890123456789012'); + expect(transaction.contexts?.trace?.parent_span_id).toBeUndefined(); + + // Different trace ID than the first span + const trace1Id = transaction.contexts?.trace?.data?.spanIdTraceId; + expect(trace1Id).toBeDefined(); + expect(trace1Id).not.toBe(traceId); + }, + }) + .start(done); +}); diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/scenario.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/scenario.ts new file mode 100644 index 000000000000..ec761a7d591d --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/scenario.ts @@ -0,0 +1,20 @@ +import { loggingTransport } from '@sentry-internal/node-integration-tests'; +import * as Sentry from '@sentry/node'; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + release: '1.0', + tracesSampleRate: 1.0, + transport: loggingTransport, +}); + +Sentry.withScope(scope => { + scope.setPropagationContext({ + parentSpanId: '1234567890123456', + spanId: '123456789012345x', + traceId: '12345678901234567890123456789012', + }); + + Sentry.startSpan({ name: 'test_span_1' }, () => undefined); + Sentry.startSpan({ name: 'test_span_2' }, () => undefined); +}); diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/test.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/test.ts new file mode 100644 index 000000000000..9a561ffd391a --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope-with-parentSpanId/test.ts @@ -0,0 +1,34 @@ +import { cleanupChildProcesses, createRunner } from '../../../../utils/runner'; + +afterAll(() => { + cleanupChildProcesses(); +}); + +test('should send manually started parallel root spans outside of root context with parentSpanId', done => { + createRunner(__dirname, 'scenario.ts') + .expect({ + transaction: { + transaction: 'test_span_1', + contexts: { + trace: { + span_id: expect.any(String), + parent_span_id: '1234567890123456', + trace_id: '12345678901234567890123456789012', + }, + }, + }, + }) + .expect({ + transaction: { + transaction: 'test_span_2', + contexts: { + trace: { + span_id: expect.any(String), + parent_span_id: '1234567890123456', + trace_id: '12345678901234567890123456789012', + }, + }, + }, + }) + .start(done); +}); diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/scenario.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/scenario.ts new file mode 100644 index 000000000000..69a9d5e2c0ef --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/scenario.ts @@ -0,0 +1,26 @@ +import { loggingTransport } from '@sentry-internal/node-integration-tests'; +import * as Sentry from '@sentry/node'; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + release: '1.0', + tracesSampleRate: 1.0, + transport: loggingTransport, +}); + +Sentry.withScope(() => { + const spanIdTraceId = Sentry.startSpan( + { + name: 'test_span_1', + }, + span1 => span1.spanContext().traceId, + ); + + Sentry.startSpan( + { + name: 'test_span_2', + attributes: { spanIdTraceId }, + }, + () => undefined, + ); +}); diff --git a/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/test.ts b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/test.ts new file mode 100644 index 000000000000..97ceaa1e382c --- /dev/null +++ b/dev-packages/node-integration-tests/suites/public-api/startSpan/parallel-spans-in-scope/test.ts @@ -0,0 +1,27 @@ +import { cleanupChildProcesses, createRunner } from '../../../../utils/runner'; + +afterAll(() => { + cleanupChildProcesses(); +}); + +test('should send manually started parallel root spans outside of root context', done => { + expect.assertions(6); + + createRunner(__dirname, 'scenario.ts') + .expect({ transaction: { transaction: 'test_span_1' } }) + .expect({ + transaction: transaction => { + expect(transaction).toBeDefined(); + const traceId = transaction.contexts?.trace?.trace_id; + expect(traceId).toBeDefined(); + expect(transaction.contexts?.trace?.parent_span_id).toBeUndefined(); + + const trace1Id = transaction.contexts?.trace?.data?.spanIdTraceId; + expect(trace1Id).toBeDefined(); + + // Same trace ID as the first span + expect(trace1Id).toBe(traceId); + }, + }) + .start(done); +}); diff --git a/packages/opentelemetry/src/trace.ts b/packages/opentelemetry/src/trace.ts index 6ba41eec51e2..1ed0fa6a1322 100644 --- a/packages/opentelemetry/src/trace.ts +++ b/packages/opentelemetry/src/trace.ts @@ -176,8 +176,9 @@ function ensureTimestampInMilliseconds(timestamp: number): number { function getContext(scope: Scope | undefined, forceTransaction: boolean | undefined): Context { const ctx = getContextForScope(scope); + // Note: If the context is the ROOT_CONTEXT, no scope is attached + // Thus we will not use the propagation context in this case, which is desired const actualScope = getScopesFromContext(ctx)?.scope; - const parentSpan = trace.getSpan(ctx); // In the case that we have no parent span, we need to "simulate" one to ensure the propagation context is correct