diff --git a/dev-packages/e2e-tests/test-applications/nextjs-14/playwright.config.ts b/dev-packages/e2e-tests/test-applications/nextjs-14/playwright.config.ts index 8448829443d6..c675d003853a 100644 --- a/dev-packages/e2e-tests/test-applications/nextjs-14/playwright.config.ts +++ b/dev-packages/e2e-tests/test-applications/nextjs-14/playwright.config.ts @@ -5,15 +5,9 @@ if (!testEnv) { throw new Error('No test env defined'); } -const config = getPlaywrightConfig( - { - startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030', - port: 3030, - }, - { - // This comes with the risk of tests leaking into each other but the tests run quite slow so we should parallelize - workers: '100%', - }, -); +const config = getPlaywrightConfig({ + startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030', + port: 3030, +}); export default config; diff --git a/dev-packages/e2e-tests/test-applications/nextjs-app-dir/playwright.config.mjs b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/playwright.config.mjs index 8448829443d6..c675d003853a 100644 --- a/dev-packages/e2e-tests/test-applications/nextjs-app-dir/playwright.config.mjs +++ b/dev-packages/e2e-tests/test-applications/nextjs-app-dir/playwright.config.mjs @@ -5,15 +5,9 @@ if (!testEnv) { throw new Error('No test env defined'); } -const config = getPlaywrightConfig( - { - startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030', - port: 3030, - }, - { - // This comes with the risk of tests leaking into each other but the tests run quite slow so we should parallelize - workers: '100%', - }, -); +const config = getPlaywrightConfig({ + startCommand: testEnv === 'development' ? 'pnpm next dev -p 3030' : 'pnpm next start -p 3030', + port: 3030, +}); export default config; diff --git a/dev-packages/opentelemetry-v2-tests/test/integration/transactions.test.ts b/dev-packages/opentelemetry-v2-tests/test/integration/transactions.test.ts index fc2702b4e390..3bdf6c113555 100644 --- a/dev-packages/opentelemetry-v2-tests/test/integration/transactions.test.ts +++ b/dev-packages/opentelemetry-v2-tests/test/integration/transactions.test.ts @@ -1,7 +1,6 @@ import type { SpanContext } from '@opentelemetry/api'; import { context, ROOT_CONTEXT, trace, TraceFlags } from '@opentelemetry/api'; import { TraceState } from '@opentelemetry/core'; -import type { SpanProcessor } from '@opentelemetry/sdk-trace-base'; import type { Event, TransactionEvent } from '@sentry/core'; import { addBreadcrumb, @@ -15,7 +14,6 @@ import { } from '@sentry/core'; import { afterEach, describe, expect, it, vi } from 'vitest'; import { SENTRY_TRACE_STATE_DSC } from '../../../../packages/opentelemetry/src/constants'; -import { SentrySpanProcessor } from '../../../../packages/opentelemetry/src/spanProcessor'; import { startInactiveSpan, startSpan } from '../../../../packages/opentelemetry/src/trace'; import { makeTraceState } from '../../../../packages/opentelemetry/src/utils/makeTraceState'; import { cleanupOtel, getProvider, getSpanProcessor, mockSdkInit } from '../helpers/mockSdkInit'; @@ -550,7 +548,60 @@ describe('Integration | Transactions', () => { expect(finishedSpans.length).toBe(0); }); - it('discards child spans that are finished after their parent span', async () => { +it('collects child spans that are finished within 5 minutes their parent span has been sent', async () => { + const timeout = 5 * 60 * 1000; + const now = Date.now(); + vi.useFakeTimers(); + vi.setSystemTime(now); + + const logs: unknown[] = []; + vi.spyOn(logger, 'log').mockImplementation(msg => logs.push(msg)); + + const transactions: Event[] = []; + + mockSdkInit({ + tracesSampleRate: 1, + beforeSendTransaction: event => { + transactions.push(event); + return null; + }, + }); + + const provider = getProvider(); + const spanProcessor = getSpanProcessor(); + + const exporter = spanProcessor ? spanProcessor['_exporter'] : undefined; + + if (!exporter) { + throw new Error('No exporter found, aborting test...'); + } + + startSpanManual({ name: 'test name' }, async span => { + const subSpan = startInactiveSpan({ name: 'inner span 1' }); + subSpan.end(); + + const subSpan2 = startInactiveSpan({ name: 'inner span 2' }); + + span.end(); + + setTimeout(() => { + subSpan2.end(); + }, timeout - 2); + }); + + vi.advanceTimersByTime(timeout - 1); + + expect(transactions).toHaveLength(2); + expect(transactions[0]?.spans).toHaveLength(1); + + const finishedSpans: any = exporter['_finishedSpanBuckets'].flatMap(bucket => + bucket ? Array.from(bucket.spans) : [], + ); + expect(finishedSpans.length).toBe(0); +}); + + it('discards child spans that are finished after 5 minutes their parent span has been sent', async () => { + const timeout = 5 * 60 * 1000; const now = Date.now(); vi.useFakeTimers(); vi.setSystemTime(now); @@ -587,10 +638,10 @@ describe('Integration | Transactions', () => { setTimeout(() => { subSpan2.end(); - }, 1); + }, timeout + 1); }); - vi.advanceTimersByTime(2); + vi.advanceTimersByTime(timeout + 2); expect(transactions).toHaveLength(1); expect(transactions[0]?.spans).toHaveLength(1); diff --git a/packages/opentelemetry/src/spanExporter.ts b/packages/opentelemetry/src/spanExporter.ts index f9c403a47dfc..fee780def708 100644 --- a/packages/opentelemetry/src/spanExporter.ts +++ b/packages/opentelemetry/src/spanExporter.ts @@ -71,6 +71,9 @@ export class SentrySpanExporter { private _finishedSpanBucketSize: number; private _spansToBucketEntry: WeakMap; private _lastCleanupTimestampInS: number; + // Essentially a a set of span ids that are already sent. The values are expiration + // times in this cache so we don't hold onto them indefinitely. + private _sentSpans: Map; public constructor(options?: { /** Lower bound of time in seconds until spans that are buffered but have not been sent as part of a transaction get cleared from memory. */ @@ -80,6 +83,48 @@ export class SentrySpanExporter { this._finishedSpanBuckets = new Array(this._finishedSpanBucketSize).fill(undefined); this._lastCleanupTimestampInS = Math.floor(Date.now() / 1000); this._spansToBucketEntry = new WeakMap(); + this._sentSpans = new Map(); + } + + /** + * Check if a span with the given ID has already been sent using the `_sentSpans` as a cache. + * Purges "expired" spans from the cache upon checking. + * @param spanId The span id to check. + * @returns Whether the span is already sent in the past X seconds. + */ + public isSpanAlreadySent(spanId: string): boolean { + const expirationTime = this._sentSpans.get(spanId); + if (expirationTime) { + if (Date.now() >= expirationTime) { + this._sentSpans.delete(spanId); // Remove expired span + } else { + return true; + } + } + return false; + } + + /** Remove "expired" span id entries from the _sentSpans cache. */ + public flushSentSpanCache(): void { + const currentTimestamp = Date.now(); + // Note, it is safe to delete items from the map as we go: https://stackoverflow.com/a/35943995/90297 + for (const [spanId, expirationTime] of this._sentSpans.entries()) { + if (expirationTime <= currentTimestamp) { + this._sentSpans.delete(spanId); + } + } + } + + /** Check if a node is a completed root node or a node whose parent has already been sent */ + public nodeIsCompletedRootNode(node: SpanNode): node is SpanNodeCompleted { + return !!node.span && (!node.parentNode || this.isSpanAlreadySent(node.parentNode.id)); + } + + /** Get all completed root nodes from a list of nodes */ + public getCompletedRootNodes(nodes: SpanNode[]): SpanNodeCompleted[] { + // TODO: We should be able to remove the explicit `node is SpanNodeCompleted` type guard + // once we stop supporting TS < 5.5 + return nodes.filter((node): node is SpanNodeCompleted => this.nodeIsCompletedRootNode(node)); } /** Export a single span. */ @@ -113,7 +158,8 @@ export class SentrySpanExporter { this._spansToBucketEntry.set(span, currentBucket); // If the span doesn't have a local parent ID (it's a root span), we're gonna flush all the ended spans - if (!getLocalParentId(span)) { + const localParentId = getLocalParentId(span); + if (!localParentId || this.isSpanAlreadySent(localParentId)) { this._clearTimeout(); // If we got a parent span, we try to send the span tree @@ -128,30 +174,29 @@ export class SentrySpanExporter { public flush(): void { this._clearTimeout(); - const finishedSpans: ReadableSpan[] = []; - this._finishedSpanBuckets.forEach(bucket => { - if (bucket) { - finishedSpans.push(...bucket.spans); - } - }); + const finishedSpans: ReadableSpan[] = this._finishedSpanBuckets.flatMap(bucket => + bucket ? Array.from(bucket.spans) : [], + ); - const sentSpans = maybeSend(finishedSpans); + this.flushSentSpanCache(); + const sentSpans = this._maybeSend(finishedSpans); + for (const span of finishedSpans) { + this._sentSpans.set(span.spanContext().spanId, Date.now() + DEFAULT_TIMEOUT * 1000); + } const sentSpanCount = sentSpans.size; - const remainingOpenSpanCount = finishedSpans.length - sentSpanCount; - DEBUG_BUILD && logger.log( `SpanExporter exported ${sentSpanCount} spans, ${remainingOpenSpanCount} spans are waiting for their parent spans to finish`, ); - sentSpans.forEach(span => { + for (const span of sentSpans) { const bucketEntry = this._spansToBucketEntry.get(span); if (bucketEntry) { bucketEntry.spans.delete(span); } - }); + } } /** Clear the exporter. */ @@ -167,59 +212,51 @@ export class SentrySpanExporter { this._flushTimeout = undefined; } } -} - -/** - * Send the given spans, but only if they are part of a finished transaction. - * - * Returns the sent spans. - * Spans remain unsent when their parent span is not yet finished. - * This will happen regularly, as child spans are generally finished before their parents. - * But it _could_ also happen because, for whatever reason, a parent span was lost. - * In this case, we'll eventually need to clean this up. - */ -function maybeSend(spans: ReadableSpan[]): Set { - const grouped = groupSpansWithParents(spans); - const sentSpans = new Set(); - const rootNodes = getCompletedRootNodes(grouped); + /** + * Send the given spans, but only if they are part of a finished transaction. + * + * Returns the sent spans. + * Spans remain unsent when their parent span is not yet finished. + * This will happen regularly, as child spans are generally finished before their parents. + * But it _could_ also happen because, for whatever reason, a parent span was lost. + * In this case, we'll eventually need to clean this up. + */ + private _maybeSend(spans: ReadableSpan[]): Set { + const grouped = groupSpansWithParents(spans); + const sentSpans = new Set(); - rootNodes.forEach(root => { - const span = root.span; - sentSpans.add(span); - const transactionEvent = createTransactionForOtelSpan(span); + const rootNodes = this.getCompletedRootNodes(grouped); - // We'll recursively add all the child spans to this array - const spans = transactionEvent.spans || []; + for (const root of rootNodes) { + const span = root.span; + sentSpans.add(span); + const transactionEvent = createTransactionForOtelSpan(span); - root.children.forEach(child => { - createAndFinishSpanForOtelSpan(child, spans, sentSpans); - }); + // We'll recursively add all the child spans to this array + const spans = transactionEvent.spans || []; - // spans.sort() mutates the array, but we do not use this anymore after this point - // so we can safely mutate it here - transactionEvent.spans = - spans.length > MAX_SPAN_COUNT - ? spans.sort((a, b) => a.start_timestamp - b.start_timestamp).slice(0, MAX_SPAN_COUNT) - : spans; + for (const child of root.children) { + createAndFinishSpanForOtelSpan(child, spans, sentSpans); + } - const measurements = timedEventsToMeasurements(span.events); - if (measurements) { - transactionEvent.measurements = measurements; - } + // spans.sort() mutates the array, but we do not use this anymore after this point + // so we can safely mutate it here + transactionEvent.spans = + spans.length > MAX_SPAN_COUNT + ? spans.sort((a, b) => a.start_timestamp - b.start_timestamp).slice(0, MAX_SPAN_COUNT) + : spans; - captureEvent(transactionEvent); - }); - - return sentSpans; -} + const measurements = timedEventsToMeasurements(span.events); + if (measurements) { + transactionEvent.measurements = measurements; + } -function nodeIsCompletedRootNode(node: SpanNode): node is SpanNodeCompleted { - return !!node.span && !node.parentNode; -} + captureEvent(transactionEvent); + } -function getCompletedRootNodes(nodes: SpanNode[]): SpanNodeCompleted[] { - return nodes.filter(nodeIsCompletedRootNode); + return sentSpans; + } } function parseSpan(span: ReadableSpan): { op?: string; origin?: SpanOrigin; source?: TransactionSource } { diff --git a/packages/opentelemetry/test/integration/transactions.test.ts b/packages/opentelemetry/test/integration/transactions.test.ts index 97d075ef5071..165871df69ca 100644 --- a/packages/opentelemetry/test/integration/transactions.test.ts +++ b/packages/opentelemetry/test/integration/transactions.test.ts @@ -561,7 +561,8 @@ describe('Integration | Transactions', () => { expect(finishedSpans.length).toBe(0); }); - it('discards child spans that are finished after their parent span', async () => { + it('collects child spans that are finished within 5 minutes their parent span has been sent', async () => { + const timeout = 5 * 60 * 1000; const now = Date.now(); vi.useFakeTimers(); vi.setSystemTime(now); @@ -603,10 +604,67 @@ describe('Integration | Transactions', () => { setTimeout(() => { subSpan2.end(); - }, 1); + }, timeout - 2); }); - vi.advanceTimersByTime(2); + vi.advanceTimersByTime(timeout - 1); + + expect(transactions).toHaveLength(2); + expect(transactions[0]?.spans).toHaveLength(1); + + const finishedSpans: any = exporter['_finishedSpanBuckets'].flatMap(bucket => + bucket ? Array.from(bucket.spans) : [], + ); + expect(finishedSpans.length).toBe(0); + }); + + it('discards child spans that are finished after 5 minutes their parent span has been sent', async () => { + const timeout = 5 * 60 * 1000; + const now = Date.now(); + vi.useFakeTimers(); + vi.setSystemTime(now); + + const logs: unknown[] = []; + vi.spyOn(logger, 'log').mockImplementation(msg => logs.push(msg)); + + const transactions: Event[] = []; + + mockSdkInit({ + tracesSampleRate: 1, + beforeSendTransaction: event => { + transactions.push(event); + return null; + }, + }); + + const provider = getProvider(); + const multiSpanProcessor = provider?.activeSpanProcessor as + | (SpanProcessor & { _spanProcessors?: SpanProcessor[] }) + | undefined; + const spanProcessor = multiSpanProcessor?.['_spanProcessors']?.find( + spanProcessor => spanProcessor instanceof SentrySpanProcessor, + ) as SentrySpanProcessor | undefined; + + const exporter = spanProcessor ? spanProcessor['_exporter'] : undefined; + + if (!exporter) { + throw new Error('No exporter found, aborting test...'); + } + + startSpanManual({ name: 'test name' }, async span => { + const subSpan = startInactiveSpan({ name: 'inner span 1' }); + subSpan.end(); + + const subSpan2 = startInactiveSpan({ name: 'inner span 2' }); + + span.end(); + + setTimeout(() => { + subSpan2.end(); + }, timeout + 1); + }); + + vi.advanceTimersByTime(timeout + 2); expect(transactions).toHaveLength(1); expect(transactions[0]?.spans).toHaveLength(1);