diff --git a/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/instrument-basic-tracer-provider.mjs b/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/instrument-basic-tracer-provider.mjs new file mode 100644 index 000000000000..114a06934170 --- /dev/null +++ b/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/instrument-basic-tracer-provider.mjs @@ -0,0 +1,10 @@ +import * as Sentry from '@sentry/node'; +import { loggingTransport } from '@sentry-internal/node-integration-tests'; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + release: '1.0', + tracesSampleRate: 1.0, + openTelemetryBasicTracerProvider: true, + transport: loggingTransport, +}); diff --git a/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/test.ts b/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/test.ts index 90cfbcee276d..1b2783fc05fb 100644 --- a/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/test.ts +++ b/dev-packages/node-integration-tests/suites/tracing/prisma-orm-v5/test.ts @@ -1,3 +1,4 @@ +import type { TransactionEvent } from '@sentry/core'; import { afterAll, describe, expect } from 'vitest'; import { cleanupChildProcesses, createEsmAndCjsTests } from '../../../utils/runner'; @@ -5,13 +6,113 @@ afterAll(() => { cleanupChildProcesses(); }); -// TODO(provider): Prisma v5 engine spans (`prisma:engine:*`) are minted by Sentry's v5 compatibility -// shim (`prismaIntegration`), which forces the engine-supplied span/trace IDs by overriding the OTel -// SDK tracer's private `_idGenerator`. Under the SentryTracerProvider the global tracer is a -// `SentryTracer`, which has no `_idGenerator`, so the shim bails out and drops every engine span, -// leaving only the `prisma:client:*` spans. v6/v7 are unaffected (they create engine spans via core's -// span APIs). Re-enable once the v5 shim can mint spans with explicit IDs under the provider. -describe.skip('Prisma ORM v5 Tests', () => { +const ADDITIONAL_DEPENDENCIES = { + '@prisma/client': '5.22.0', + prisma: '5.22.0', +}; + +// Prisma v5 engine spans are minted by Sentry's v5 compatibility shim through Sentry's +// provider-agnostic span APIs, so the same span tree must be produced under both the default +// SentryTracerProvider and the opt-in OTel BasicTracerProvider (`openTelemetryBasicTracerProvider`). +function expectPrismaV5Spans(transaction: TransactionEvent): void { + expect(transaction.transaction).toBe('Test Transaction'); + const spans = transaction.spans || []; + expect(spans.length).toBeGreaterThanOrEqual(5); + + // Valid parents are the transaction root or any other span within the transaction. + const validParentIds = new Set([transaction.contexts?.trace?.span_id, ...spans.map(s => s.span_id)]); + + const operationSpans = spans.filter(s => s.description === 'prisma:client:operation'); + expect(operationSpans.length).toBeGreaterThanOrEqual(1); + + // The db-query spans are materialized from the raw engine event; assert they nest inside the + // transaction rather than dangling as orphans. + const dbSpans = spans.filter(s => s.op === 'db'); + expect(dbSpans.length).toBeGreaterThanOrEqual(1); + dbSpans.forEach(dbSpan => { + expect(validParentIds.has(dbSpan.parent_span_id)).toBe(true); + }); + + const txSpan = spans.find(s => s.description === 'prisma:client:transaction'); + expect(txSpan).toBeDefined(); + + expect(spans).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + data: { + method: 'create', + model: 'User', + name: 'User.create', + 'sentry.origin': 'auto.db.otel.prisma', + }, + description: 'prisma:client:operation', + status: 'ok', + }), + expect.objectContaining({ + data: { + method: 'findMany', + model: 'User', + name: 'User.findMany', + 'sentry.origin': 'auto.db.otel.prisma', + }, + description: 'prisma:client:operation', + status: 'ok', + }), + expect.objectContaining({ + data: { + 'sentry.origin': 'auto.db.otel.prisma', + }, + description: 'prisma:client:serialize', + status: 'ok', + }), + expect.objectContaining({ + data: { + 'sentry.origin': 'auto.db.otel.prisma', + }, + description: 'prisma:client:connect', + status: 'ok', + }), + expect.objectContaining({ + data: { + 'db.statement': expect.stringContaining('INSERT INTO'), + 'db.system': 'postgresql', + 'otel.kind': 'CLIENT', + 'sentry.op': 'db', + 'sentry.origin': 'auto.db.otel.prisma', + }, + op: 'db', + description: expect.stringContaining('INSERT INTO'), + status: 'ok', + }), + expect.objectContaining({ + data: { + 'db.statement': expect.stringContaining('SELECT'), + 'db.system': 'postgresql', + 'otel.kind': 'CLIENT', + 'sentry.op': 'db', + 'sentry.origin': 'auto.db.otel.prisma', + }, + op: 'db', + description: expect.stringContaining('SELECT'), + status: 'ok', + }), + expect.objectContaining({ + data: { + 'db.statement': expect.stringContaining('DELETE'), + 'db.system': 'postgresql', + 'otel.kind': 'CLIENT', + 'sentry.op': 'db', + 'sentry.origin': 'auto.db.otel.prisma', + }, + op: 'db', + description: expect.stringContaining('DELETE'), + status: 'ok', + }), + ]), + ); +} + +describe('Prisma ORM v5 Tests', () => { createEsmAndCjsTests( __dirname, 'scenario.mjs', @@ -23,135 +124,39 @@ describe.skip('Prisma ORM v5 Tests', () => { workingDirectory: [cwd], setupCommand: 'yarn prisma generate && yarn prisma migrate dev -n sentry-test', }) - .expect({ - transaction: transaction => { - expect(transaction.transaction).toBe('Test Transaction'); - const spans = transaction.spans || []; - expect(spans.length).toBeGreaterThanOrEqual(5); - - // Valid parents are the transaction root or any other span within the transaction. - const validParentIds = new Set([transaction.contexts?.trace?.span_id, ...spans.map(s => s.span_id)]); - - const operationSpans = spans.filter(s => s.description === 'prisma:client:operation'); - expect(operationSpans.length).toBeGreaterThanOrEqual(1); - - // The db-query spans are materialized from the raw engine event; assert they nest inside the - // transaction rather than dangling as orphans. - const dbSpans = spans.filter(s => s.op === 'db'); - expect(dbSpans.length).toBeGreaterThanOrEqual(1); - dbSpans.forEach(dbSpan => { - expect(validParentIds.has(dbSpan.parent_span_id)).toBe(true); - }); - - const txSpan = spans.find(s => s.description === 'prisma:client:transaction'); - expect(txSpan).toBeDefined(); - - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - method: 'create', - model: 'User', - name: 'User.create', - 'sentry.origin': 'auto.db.otel.prisma', - }, - description: 'prisma:client:operation', - status: 'ok', - }), - ); - - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'sentry.origin': 'auto.db.otel.prisma', - }, - description: 'prisma:client:serialize', - status: 'ok', - }), - ); + .expect({ transaction: expectPrismaV5Spans }) + .start() + .completed(); + }); + }, + { + additionalDependencies: ADDITIONAL_DEPENDENCIES, + copyPaths: ['prisma', 'docker-compose.yml'], + }, + ); +}); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'sentry.origin': 'auto.db.otel.prisma', - }, - description: 'prisma:client:connect', - status: 'ok', - }), - ); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - method: 'findMany', - model: 'User', - name: 'User.findMany', - 'sentry.origin': 'auto.db.otel.prisma', - }, - description: 'prisma:client:operation', - status: 'ok', - }), - ); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'sentry.origin': 'auto.db.otel.prisma', - }, - description: 'prisma:client:serialize', - status: 'ok', - }), - ); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'db.statement': expect.stringContaining('INSERT INTO'), - 'db.system': 'postgresql', - 'otel.kind': 'CLIENT', - 'sentry.op': 'db', - 'sentry.origin': 'auto.db.otel.prisma', - }, - op: 'db', - description: expect.stringContaining('INSERT INTO'), - status: 'ok', - }), - ); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'db.statement': expect.stringContaining('SELECT'), - 'db.system': 'postgresql', - 'otel.kind': 'CLIENT', - 'sentry.op': 'db', - 'sentry.origin': 'auto.db.otel.prisma', - }, - op: 'db', - description: expect.stringContaining('SELECT'), - status: 'ok', - }), - ); - expect(spans).toContainEqual( - expect.objectContaining({ - data: { - 'db.statement': expect.stringContaining('DELETE'), - 'db.system': 'postgresql', - 'otel.kind': 'CLIENT', - 'sentry.op': 'db', - 'sentry.origin': 'auto.db.otel.prisma', - }, - op: 'db', - description: expect.stringContaining('DELETE'), - status: 'ok', - }), - ); - }, +// The BasicTracerProvider path is opt-in via `openTelemetryBasicTracerProvider: true`; it must produce +// the same Prisma v5 span tree as the default SentryTracerProvider. +describe('Prisma ORM v5 Tests (BasicTracerProvider)', () => { + createEsmAndCjsTests( + __dirname, + 'scenario.mjs', + 'instrument-basic-tracer-provider.mjs', + (createRunner, test, _mode, cwd) => { + test('should instrument PostgreSQL queries from Prisma ORM', { timeout: 75_000 }, async () => { + await createRunner() + .withDockerCompose({ + workingDirectory: [cwd], + setupCommand: 'yarn prisma generate && yarn prisma migrate dev -n sentry-test', }) + .expect({ transaction: expectPrismaV5Spans }) .start() .completed(); }); }, { - additionalDependencies: { - '@prisma/client': '5.22.0', - prisma: '5.22.0', - }, + additionalDependencies: ADDITIONAL_DEPENDENCIES, copyPaths: ['prisma', 'docker-compose.yml'], }, ); diff --git a/packages/node/src/integrations/tracing/prisma/index.ts b/packages/node/src/integrations/tracing/prisma/index.ts index 93e9109a6440..9b28af687df3 100644 --- a/packages/node/src/integrations/tracing/prisma/index.ts +++ b/packages/node/src/integrations/tracing/prisma/index.ts @@ -1,9 +1,16 @@ -import type { Link, Tracer } from '@opentelemetry/api'; -import { context, SpanKind, trace, TraceFlags } from '@opentelemetry/api'; import type { Instrumentation } from '@opentelemetry/instrumentation'; -import type { IdGenerator } from '@opentelemetry/sdk-trace-base'; -import { consoleSandbox, defineIntegration, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, spanToJSON } from '@sentry/core'; +import type { Span } from '@sentry/core'; +import { + debug, + defineIntegration, + LRUMap, + SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, + SPAN_KIND, + spanToJSON, + startInactiveSpan, +} from '@sentry/core'; import { generateInstrumentOnce } from '@sentry/node-core'; +import { DEBUG_BUILD } from '../../../debug-build'; import { PrismaInstrumentation } from './vendored/instrumentation'; import type { PrismaV5TracingHelper } from './vendored/v5-tracing-helper'; import type { PrismaV6TracingHelper } from './vendored/v6-tracing-helper'; @@ -49,9 +56,70 @@ function getPrismaTracingHelper(): unknown | undefined { return prismaTracingHelper; } -type TracerWithIdGenerator = Tracer & { - _idGenerator?: IdGenerator; -}; +// Prisma v5 dispatches engine spans (`prisma:engine:*`, which carry the SQL `db.statement`) one batch +// at a time, out of order, and detached from the active span, naming their parent only by id: a span +// references either a client span (by the Sentry span id Prisma learned via `getTraceParent`) or a +// sibling engine span (by the engine's own id), and a batch may not contain the parent it references. +// By the time the engine reports them the client span may already have ended, so `getActiveSpan()` +// can't be used to find it. `prismaSpanRegistry` maps span ids to their Sentry span, and an engine +// span whose parent isn't registered yet waits in `pendingEngineSpans` until a later batch registers it. +const MAX_TRACKED_PRISMA_SPANS = 1000; +const prismaSpanRegistry = new LRUMap(MAX_TRACKED_PRISMA_SPANS); +const pendingEngineSpans: V5EngineSpan[] = []; + +/** Register a span so v5 engine spans can later resolve it as a parent by the id Prisma reports it under. */ +function registerPrismaSpan(id: string, span: Span): void { + prismaSpanRegistry.set(id, span); +} + +/** + * Create every pending v5 engine span whose parent is now registered, repeating until no further span + * resolves (so a child queued before its parent is created once the parent arrives in a later batch). + * Each span is created under its resolved parent and registered by its engine id so its own children + * can find it; origin, the `prisma:engine:db_query` to SQL rename, and the `db.system` backfill are + * applied by the `spanStart` hook, exactly as for v6/v7 engine spans. + */ +function createResolvedEngineSpans(): void { + // Terminates: `createdSpan` is only set true right after a `splice`, so every pass that keeps the + // loop going strictly shrinks the finite `pendingEngineSpans`; a pass that resolves nothing exits. + let createdSpan = true; + while (createdSpan) { + createdSpan = false; + for (let i = pendingEngineSpans.length - 1; i >= 0; i--) { + const engineSpan = pendingEngineSpans[i]!; + const parentSpan = prismaSpanRegistry.get(engineSpan.parent_span_id); + if (!parentSpan) { + continue; + } + + const span = startInactiveSpan({ + name: engineSpan.name, + attributes: engineSpan.attributes, + kind: engineSpan.kind === 'client' ? SPAN_KIND.CLIENT : SPAN_KIND.INTERNAL, + startTime: engineSpan.start_time, + parentSpan, + }); + registerPrismaSpan(engineSpan.span_id, span); + + // Engine links reference other engine spans by their engine id; re-point them at the Sentry spans + // we minted (mirroring v6/v7's `dispatchEngineSpan`). Links must be added before the span ends, + // since the SentryTracerProvider seals spans on end. Links to spans we haven't created are dropped. + if (engineSpan.links) { + span.addLinks( + engineSpan.links.flatMap(link => { + const linkedSpan = prismaSpanRegistry.get(link.span_id); + return linkedSpan ? [{ context: linkedSpan.spanContext() }] : []; + }), + ); + } + + span.end(engineSpan.end_time); + + pendingEngineSpans.splice(i, 1); + createdSpan = true; + } + } +} interface PrismaOptions { /** @@ -73,86 +141,26 @@ class SentryPrismaInteropInstrumentation extends PrismaInstrumentation { super.enable(); // The PrismaIntegration (super class) defines a global variable `global["PRISMA_INSTRUMENTATION"]` when `enable()` is called. This global variable holds a "TracingHelper" which Prisma uses internally to create tracing data. It's their way of not depending on OTEL with their main package. The sucky thing is, prisma broke the interface of the tracing helper with the v6 major update. This means that if you use Prisma 5 with the v6 instrumentation (or vice versa) Prisma just blows up, because tries to call methods on the helper that no longer exist. - // Because we actually want to use the v6 instrumentation and not blow up in Prisma 5 user's faces, what we're doing here is backfilling the v5 method (`createEngineSpan`) with a noop so that no longer crashes when it attempts to call that function. + // Because we actually want to use the v6/v7 instrumentation and not blow up in Prisma 5 users' faces, we backfill the v5-only `createEngineSpan` method so v5 engine spans are minted through Sentry's span APIs instead of crashing. const prismaTracingHelper = getPrismaTracingHelper(); if (isPrismaV6TracingHelper(prismaTracingHelper)) { - // Inspired & adjusted from https://github.com/prisma/prisma/tree/5.22.0/packages/instrumentation (prismaTracingHelper as CompatibilityLayerTraceHelper).createEngineSpan = ( engineSpanEvent: V5EngineSpanEvent, ) => { - const tracer = trace.getTracer('prismaV5Compatibility') as TracerWithIdGenerator; - - // Prisma v5 relies on being able to create spans with a specific span & trace ID - // this is no longer possible in OTEL v2, there is no public API to do this anymore - // So in order to kind of hack this possibility, we rely on the internal `_idGenerator` property - // This is used to generate the random IDs, and we overwrite this temporarily to generate static IDs - // This is flawed and may not work, e.g. if the code is bundled and the private property is renamed - // in such cases, these spans will not be captured and some Prisma spans will be missing - const initialIdGenerator = tracer._idGenerator; - - if (!initialIdGenerator) { - consoleSandbox(() => { - // eslint-disable-next-line no-console - console.warn( - '[Sentry] Could not find _idGenerator on tracer, skipping Prisma v5 compatibility - some Prisma spans may be missing!', - ); - }); - - return; - } - - try { - engineSpanEvent.spans.forEach(engineSpan => { - const kind = engineSpan.kind === 'client' ? SpanKind.CLIENT : SpanKind.INTERNAL; - - const parentSpanId = engineSpan.parent_span_id; - const spanId = engineSpan.span_id; - const traceId = engineSpan.trace_id; - - const links: Link[] | undefined = engineSpan.links?.map(link => { - return { - context: { - traceId: link.trace_id, - spanId: link.span_id, - traceFlags: TraceFlags.SAMPLED, - }, - }; - }); - - const ctx = trace.setSpanContext(context.active(), { - traceId, - spanId: parentSpanId, - traceFlags: TraceFlags.SAMPLED, - }); - - context.with(ctx, () => { - const temporaryIdGenerator: IdGenerator = { - generateTraceId: () => { - return traceId; - }, - generateSpanId: () => { - return spanId; - }, - }; - - tracer._idGenerator = temporaryIdGenerator; - - const span = tracer.startSpan(engineSpan.name, { - kind, - links, - startTime: engineSpan.start_time, - attributes: engineSpan.attributes, - }); - - span.end(engineSpan.end_time); - - tracer._idGenerator = initialIdGenerator; - }); - }); - } finally { - // Ensure we always restore this at the end, even if something errors - tracer._idGenerator = initialIdGenerator; + pendingEngineSpans.push(...engineSpanEvent.spans); + + // Resolve before capping so a span is only ever dropped after a full resolution attempt, never + // before it had a chance to find its parent. What remains are orphans whose parent was never + // registered (e.g. evicted from the registry under sustained load); cap that backlog so it can't + // grow without bound. + createResolvedEngineSpans(); + + const overflow = pendingEngineSpans.length - MAX_TRACKED_PRISMA_SPANS; + if (overflow > 0) { + DEBUG_BUILD && + debug.log(`[Prisma] Dropping ${overflow} unresolved v5 engine span(s) whose parent was never registered.`); + pendingEngineSpans.splice(0, overflow); } }; } @@ -197,6 +205,15 @@ export const prismaIntegration = defineIntegration((options?: PrismaOptions) => const spanJSON = spanToJSON(span); if (spanJSON.description?.startsWith('prisma:')) { span.setAttribute(SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, 'auto.db.otel.prisma'); + + // Register client spans so a v5 engine span (dispatched later, detached) can resolve one as a + // parent by the Sentry span id Prisma reported via `getTraceParent` (see + // `createResolvedEngineSpans`). Only client spans are referenced this way; engine spans + // reference their parent by the engine's own id and are registered in `createResolvedEngineSpans`, + // so registering them here too would just leave entries that are never looked up. + if (spanJSON.description.startsWith('prisma:client:')) { + registerPrismaSpan(span.spanContext().spanId, span); + } } // Make sure we use the query text as the span name, for ex. SELECT * FROM "User" WHERE "id" = $1.