From 7e9a03803d761fdf661f305fdd58cf57eb2190c6 Mon Sep 17 00:00:00 2001 From: Nicolas Hrubec Date: Wed, 28 Aug 2024 17:28:20 +0200 Subject: [PATCH] feat(nestjs): Automatic instrumentation of nestjs interceptors after route execution (#13264) Adding a span 'Interceptor - After Span' to improve instrumentation for operations happening after the route execution is done. Tracking what happens in individual interceptors after the route is hard, so currently we create one span to trace everything that happens after the route is executed. --- .../nestjs-basic/src/app.controller.ts | 12 +- .../src/async-example.interceptor.ts | 17 + .../nestjs-basic/src/example-1.interceptor.ts | 15 + ...nterceptor.ts => example-2.interceptor.ts} | 4 +- .../nestjs-basic/tests/transactions.test.ts | 307 +++++++++++++++++- .../node-nestjs-basic/src/app.controller.ts | 12 +- .../src/async-example.interceptor.ts | 17 + .../src/example-1.interceptor.ts | 15 + .../src/example-2.interceptor.ts | 10 + .../src/example.interceptor.ts | 11 - .../tests/transactions.test.ts | 307 +++++++++++++++++- .../src/integrations/tracing/nest/helpers.ts | 29 +- .../nest/sentry-nest-instrumentation.ts | 96 ++++-- .../src/integrations/tracing/nest/types.ts | 10 +- 14 files changed, 794 insertions(+), 68 deletions(-) create mode 100644 dev-packages/e2e-tests/test-applications/nestjs-basic/src/async-example.interceptor.ts create mode 100644 dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-1.interceptor.ts rename dev-packages/e2e-tests/test-applications/nestjs-basic/src/{example.interceptor.ts => example-2.interceptor.ts} (65%) create mode 100644 dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/async-example.interceptor.ts create mode 100644 dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-1.interceptor.ts create mode 100644 dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-2.interceptor.ts delete mode 100644 dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example.interceptor.ts diff --git a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/app.controller.ts b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/app.controller.ts index 9cda3c96f9a6..1649cdb94b5f 100644 --- a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/app.controller.ts +++ b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/app.controller.ts @@ -1,11 +1,13 @@ import { Controller, Get, Param, ParseIntPipe, UseFilters, UseGuards, UseInterceptors } from '@nestjs/common'; import { flush } from '@sentry/nestjs'; import { AppService } from './app.service'; +import { AsyncInterceptor } from './async-example.interceptor'; +import { ExampleInterceptor1 } from './example-1.interceptor'; +import { ExampleInterceptor2 } from './example-2.interceptor'; import { ExampleExceptionGlobalFilter } from './example-global-filter.exception'; import { ExampleExceptionLocalFilter } from './example-local-filter.exception'; import { ExampleLocalFilter } from './example-local.filter'; import { ExampleGuard } from './example.guard'; -import { ExampleInterceptor } from './example.interceptor'; @Controller() @UseFilters(ExampleLocalFilter) @@ -29,11 +31,17 @@ export class AppController { } @Get('test-interceptor-instrumentation') - @UseInterceptors(ExampleInterceptor) + @UseInterceptors(ExampleInterceptor1, ExampleInterceptor2) testInterceptorInstrumentation() { return this.appService.testSpan(); } + @Get('test-async-interceptor-instrumentation') + @UseInterceptors(AsyncInterceptor) + testAsyncInterceptorInstrumentation() { + return this.appService.testSpan(); + } + @Get('test-pipe-instrumentation/:id') testPipeInstrumentation(@Param('id', ParseIntPipe) id: number) { return { value: id }; diff --git a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/async-example.interceptor.ts b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/async-example.interceptor.ts new file mode 100644 index 000000000000..ac0ee60acc51 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/async-example.interceptor.ts @@ -0,0 +1,17 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; +import * as Sentry from '@sentry/nestjs'; +import { tap } from 'rxjs'; + +@Injectable() +export class AsyncInterceptor implements NestInterceptor { + intercept(context: ExecutionContext, next: CallHandler) { + Sentry.startSpan({ name: 'test-async-interceptor-span' }, () => {}); + return Promise.resolve( + next.handle().pipe( + tap(() => { + Sentry.startSpan({ name: 'test-async-interceptor-span-after-route' }, () => {}); + }), + ), + ); + } +} diff --git a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-1.interceptor.ts b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-1.interceptor.ts new file mode 100644 index 000000000000..81c9f70d30e2 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-1.interceptor.ts @@ -0,0 +1,15 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; +import * as Sentry from '@sentry/nestjs'; +import { tap } from 'rxjs'; + +@Injectable() +export class ExampleInterceptor1 implements NestInterceptor { + intercept(context: ExecutionContext, next: CallHandler) { + Sentry.startSpan({ name: 'test-interceptor-span-1' }, () => {}); + return next.handle().pipe( + tap(() => { + Sentry.startSpan({ name: 'test-interceptor-span-after-route' }, () => {}); + }), + ); + } +} diff --git a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example.interceptor.ts b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-2.interceptor.ts similarity index 65% rename from dev-packages/e2e-tests/test-applications/nestjs-basic/src/example.interceptor.ts rename to dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-2.interceptor.ts index 75c301b4cffc..2cf9dfb9e043 100644 --- a/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example.interceptor.ts +++ b/dev-packages/e2e-tests/test-applications/nestjs-basic/src/example-2.interceptor.ts @@ -2,9 +2,9 @@ import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nes import * as Sentry from '@sentry/nestjs'; @Injectable() -export class ExampleInterceptor implements NestInterceptor { +export class ExampleInterceptor2 implements NestInterceptor { intercept(context: ExecutionContext, next: CallHandler) { - Sentry.startSpan({ name: 'test-interceptor-span' }, () => {}); + Sentry.startSpan({ name: 'test-interceptor-span-2' }, () => {}); return next.handle().pipe(); } } diff --git a/dev-packages/e2e-tests/test-applications/nestjs-basic/tests/transactions.test.ts b/dev-packages/e2e-tests/test-applications/nestjs-basic/tests/transactions.test.ts index 555b6357ade8..e33e63f319ca 100644 --- a/dev-packages/e2e-tests/test-applications/nestjs-basic/tests/transactions.test.ts +++ b/dev-packages/e2e-tests/test-applications/nestjs-basic/tests/transactions.test.ts @@ -341,7 +341,7 @@ test('API route transaction includes nest pipe span for invalid request', async ); }); -test('API route transaction includes nest interceptor span. Spans created in and after interceptor are nested correctly', async ({ +test('API route transaction includes nest interceptor spans before route execution. Spans created in and after interceptor are nested correctly', async ({ baseURL, }) => { const pageloadTransactionEventPromise = waitForTransaction('nestjs-basic', transactionEvent => { @@ -356,6 +356,7 @@ test('API route transaction includes nest interceptor span. Spans created in and const transactionEvent = await pageloadTransactionEventPromise; + // check if interceptor spans before route execution exist expect(transactionEvent).toEqual( expect.objectContaining({ spans: expect.arrayContaining([ @@ -366,7 +367,22 @@ test('API route transaction includes nest interceptor span. Spans created in and 'sentry.op': 'middleware.nestjs', 'sentry.origin': 'auto.middleware.nestjs', }, - description: 'ExampleInterceptor', + description: 'ExampleInterceptor1', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'ExampleInterceptor2', parent_span_id: expect.any(String), start_timestamp: expect.any(Number), timestamp: expect.any(Number), @@ -378,9 +394,13 @@ test('API route transaction includes nest interceptor span. Spans created in and }), ); - const exampleInterceptorSpan = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor'); - const exampleInterceptorSpanId = exampleInterceptorSpan?.span_id; + // get interceptor spans + const exampleInterceptor1Span = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor1'); + const exampleInterceptor1SpanId = exampleInterceptor1Span?.span_id; + const exampleInterceptor2Span = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor2'); + const exampleInterceptor2SpanId = exampleInterceptor2Span?.span_id; + // check if manually started spans exist expect(transactionEvent).toEqual( expect.objectContaining({ spans: expect.arrayContaining([ @@ -399,7 +419,105 @@ test('API route transaction includes nest interceptor span. Spans created in and span_id: expect.any(String), trace_id: expect.any(String), data: expect.any(Object), - description: 'test-interceptor-span', + description: 'test-interceptor-span-1', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-interceptor-span-2', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testInterceptor1Span = transactionEvent.spans.find(span => span.description === 'test-interceptor-span-1'); + const testInterceptor2Span = transactionEvent.spans.find(span => span.description === 'test-interceptor-span-2'); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'ExampleInterceptor1' is the parent of 'test-interceptor-span-1' + expect(testInterceptor1Span.parent_span_id).toBe(exampleInterceptor1SpanId); + + // 'ExampleInterceptor1' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptor1SpanId); + + // 'ExampleInterceptor2' is the parent of 'test-interceptor-span-2' + expect(testInterceptor2Span.parent_span_id).toBe(exampleInterceptor2SpanId); + + // 'ExampleInterceptor2' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptor2SpanId); +}); + +test('API route transaction includes exactly one nest interceptor span after route execution. Spans created in controller and in interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans after route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'Interceptors - After Route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // check that exactly one after route span is sent + const allInterceptorSpansAfterRoute = transactionEvent.spans.filter( + span => span.description === 'Interceptors - After Route', + ); + expect(allInterceptorSpansAfterRoute.length).toBe(1); + + // get interceptor span + const exampleInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'Interceptors - After Route', + ); + const exampleInterceptorSpanAfterRouteId = exampleInterceptorSpanAfterRoute?.span_id; + + // check if manually started span in interceptor after route exists + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-interceptor-span-after-route', parent_span_id: expect.any(String), start_timestamp: expect.any(Number), timestamp: expect.any(Number), @@ -411,12 +529,181 @@ test('API route transaction includes nest interceptor span. Spans created in and ); // verify correct span parent-child relationships - const testInterceptorSpan = transactionEvent.spans.find(span => span.description === 'test-interceptor-span'); + const testInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'test-interceptor-span-after-route', + ); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'Interceptor - After Route' is the parent of 'test-interceptor-span-after-route' + expect(testInterceptorSpanAfterRoute.parent_span_id).toBe(exampleInterceptorSpanAfterRouteId); + + // 'Interceptor - After Route' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanAfterRouteId); +}); + +test('API route transaction includes nest async interceptor spans before route execution. Spans created in and after async interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-async-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-async-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans before route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'AsyncInterceptor', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // get interceptor spans + const exampleAsyncInterceptor = transactionEvent.spans.find(span => span.description === 'AsyncInterceptor'); + const exampleAsyncInterceptorSpanId = exampleAsyncInterceptor?.span_id; + + // check if manually started spans exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-controller-span', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-async-interceptor-span', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testAsyncInterceptorSpan = transactionEvent.spans.find( + span => span.description === 'test-async-interceptor-span', + ); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'AsyncInterceptor' is the parent of 'test-async-interceptor-span' + expect(testAsyncInterceptorSpan.parent_span_id).toBe(exampleAsyncInterceptorSpanId); + + // 'AsyncInterceptor' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleAsyncInterceptorSpanId); +}); + +test('API route transaction includes exactly one nest async interceptor span after route execution. Spans created in controller and in async interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-async-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-async-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans after route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'Interceptors - After Route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // check that exactly one after route span is sent + const allInterceptorSpansAfterRoute = transactionEvent.spans.filter( + span => span.description === 'Interceptors - After Route', + ); + expect(allInterceptorSpansAfterRoute.length).toBe(1); + + // get interceptor span + const exampleInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'Interceptors - After Route', + ); + const exampleInterceptorSpanAfterRouteId = exampleInterceptorSpanAfterRoute?.span_id; + + // check if manually started span in interceptor after route exists + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-async-interceptor-span-after-route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'test-async-interceptor-span-after-route', + ); const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); - // 'ExampleInterceptor' is the parent of 'test-interceptor-span' - expect(testInterceptorSpan.parent_span_id).toBe(exampleInterceptorSpanId); + // 'Interceptor - After Route' is the parent of 'test-interceptor-span-after-route' + expect(testInterceptorSpanAfterRoute.parent_span_id).toBe(exampleInterceptorSpanAfterRouteId); - // 'ExampleInterceptor' is NOT the parent of 'test-controller-span' - expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanId); + // 'Interceptor - After Route' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanAfterRouteId); }); diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/app.controller.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/app.controller.ts index ec0a921da2c4..1f141dc0f966 100644 --- a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/app.controller.ts +++ b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/app.controller.ts @@ -1,8 +1,10 @@ import { Controller, Get, Param, ParseIntPipe, UseGuards, UseInterceptors } from '@nestjs/common'; import { flush } from '@sentry/nestjs'; import { AppService } from './app.service'; +import { AsyncInterceptor } from './async-example.interceptor'; +import { ExampleInterceptor1 } from './example-1.interceptor'; +import { ExampleInterceptor2 } from './example-2.interceptor'; import { ExampleGuard } from './example.guard'; -import { ExampleInterceptor } from './example.interceptor'; @Controller() export class AppController { @@ -25,11 +27,17 @@ export class AppController { } @Get('test-interceptor-instrumentation') - @UseInterceptors(ExampleInterceptor) + @UseInterceptors(ExampleInterceptor1, ExampleInterceptor2) testInterceptorInstrumentation() { return this.appService.testSpan(); } + @Get('test-async-interceptor-instrumentation') + @UseInterceptors(AsyncInterceptor) + testAsyncInterceptorInstrumentation() { + return this.appService.testSpan(); + } + @Get('test-pipe-instrumentation/:id') testPipeInstrumentation(@Param('id', ParseIntPipe) id: number) { return { value: id }; diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/async-example.interceptor.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/async-example.interceptor.ts new file mode 100644 index 000000000000..ac0ee60acc51 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/async-example.interceptor.ts @@ -0,0 +1,17 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; +import * as Sentry from '@sentry/nestjs'; +import { tap } from 'rxjs'; + +@Injectable() +export class AsyncInterceptor implements NestInterceptor { + intercept(context: ExecutionContext, next: CallHandler) { + Sentry.startSpan({ name: 'test-async-interceptor-span' }, () => {}); + return Promise.resolve( + next.handle().pipe( + tap(() => { + Sentry.startSpan({ name: 'test-async-interceptor-span-after-route' }, () => {}); + }), + ), + ); + } +} diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-1.interceptor.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-1.interceptor.ts new file mode 100644 index 000000000000..81c9f70d30e2 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-1.interceptor.ts @@ -0,0 +1,15 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; +import * as Sentry from '@sentry/nestjs'; +import { tap } from 'rxjs'; + +@Injectable() +export class ExampleInterceptor1 implements NestInterceptor { + intercept(context: ExecutionContext, next: CallHandler) { + Sentry.startSpan({ name: 'test-interceptor-span-1' }, () => {}); + return next.handle().pipe( + tap(() => { + Sentry.startSpan({ name: 'test-interceptor-span-after-route' }, () => {}); + }), + ); + } +} diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-2.interceptor.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-2.interceptor.ts new file mode 100644 index 000000000000..2cf9dfb9e043 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example-2.interceptor.ts @@ -0,0 +1,10 @@ +import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; +import * as Sentry from '@sentry/nestjs'; + +@Injectable() +export class ExampleInterceptor2 implements NestInterceptor { + intercept(context: ExecutionContext, next: CallHandler) { + Sentry.startSpan({ name: 'test-interceptor-span-2' }, () => {}); + return next.handle().pipe(); + } +} diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example.interceptor.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example.interceptor.ts deleted file mode 100644 index 260c1798449f..000000000000 --- a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/src/example.interceptor.ts +++ /dev/null @@ -1,11 +0,0 @@ -import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common'; -import * as Sentry from '@sentry/nestjs'; -import { Observable } from 'rxjs'; - -@Injectable() -export class ExampleInterceptor implements NestInterceptor { - intercept(context: ExecutionContext, next: CallHandler): Observable { - Sentry.startSpan({ name: 'test-interceptor-span' }, () => {}); - return next.handle().pipe(); - } -} diff --git a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/tests/transactions.test.ts b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/tests/transactions.test.ts index cb04bc06839e..eb52dfe98585 100644 --- a/dev-packages/e2e-tests/test-applications/node-nestjs-basic/tests/transactions.test.ts +++ b/dev-packages/e2e-tests/test-applications/node-nestjs-basic/tests/transactions.test.ts @@ -339,7 +339,7 @@ test('API route transaction includes nest pipe span for invalid request', async ); }); -test('API route transaction includes nest interceptor span. Spans created in and after interceptor are nested correctly', async ({ +test('API route transaction includes nest interceptor spans before route execution. Spans created in and after interceptor are nested correctly', async ({ baseURL, }) => { const pageloadTransactionEventPromise = waitForTransaction('node-nestjs-basic', transactionEvent => { @@ -354,6 +354,7 @@ test('API route transaction includes nest interceptor span. Spans created in and const transactionEvent = await pageloadTransactionEventPromise; + // check if interceptor spans before route execution exist expect(transactionEvent).toEqual( expect.objectContaining({ spans: expect.arrayContaining([ @@ -364,7 +365,22 @@ test('API route transaction includes nest interceptor span. Spans created in and 'sentry.op': 'middleware.nestjs', 'sentry.origin': 'auto.middleware.nestjs', }, - description: 'ExampleInterceptor', + description: 'ExampleInterceptor1', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'ExampleInterceptor2', parent_span_id: expect.any(String), start_timestamp: expect.any(Number), timestamp: expect.any(Number), @@ -376,9 +392,13 @@ test('API route transaction includes nest interceptor span. Spans created in and }), ); - const exampleInterceptorSpan = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor'); - const exampleInterceptorSpanId = exampleInterceptorSpan?.span_id; + // get interceptor spans + const exampleInterceptor1Span = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor1'); + const exampleInterceptor1SpanId = exampleInterceptor1Span?.span_id; + const exampleInterceptor2Span = transactionEvent.spans.find(span => span.description === 'ExampleInterceptor2'); + const exampleInterceptor2SpanId = exampleInterceptor2Span?.span_id; + // check if manually started spans exist expect(transactionEvent).toEqual( expect.objectContaining({ spans: expect.arrayContaining([ @@ -397,7 +417,105 @@ test('API route transaction includes nest interceptor span. Spans created in and span_id: expect.any(String), trace_id: expect.any(String), data: expect.any(Object), - description: 'test-interceptor-span', + description: 'test-interceptor-span-1', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-interceptor-span-2', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testInterceptor1Span = transactionEvent.spans.find(span => span.description === 'test-interceptor-span-1'); + const testInterceptor2Span = transactionEvent.spans.find(span => span.description === 'test-interceptor-span-2'); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'ExampleInterceptor1' is the parent of 'test-interceptor-span-1' + expect(testInterceptor1Span.parent_span_id).toBe(exampleInterceptor1SpanId); + + // 'ExampleInterceptor1' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptor1SpanId); + + // 'ExampleInterceptor2' is the parent of 'test-interceptor-span-2' + expect(testInterceptor2Span.parent_span_id).toBe(exampleInterceptor2SpanId); + + // 'ExampleInterceptor2' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptor2SpanId); +}); + +test('API route transaction includes exactly one nest interceptor span after route execution. Spans created in controller and in interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('node-nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans after route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'Interceptors - After Route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // check that exactly one after route span is sent + const allInterceptorSpansAfterRoute = transactionEvent.spans.filter( + span => span.description === 'Interceptors - After Route', + ); + expect(allInterceptorSpansAfterRoute.length).toBe(1); + + // get interceptor span + const exampleInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'Interceptors - After Route', + ); + const exampleInterceptorSpanAfterRouteId = exampleInterceptorSpanAfterRoute?.span_id; + + // check if manually started span in interceptor after route exists + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-interceptor-span-after-route', parent_span_id: expect.any(String), start_timestamp: expect.any(Number), timestamp: expect.any(Number), @@ -409,12 +527,181 @@ test('API route transaction includes nest interceptor span. Spans created in and ); // verify correct span parent-child relationships - const testInterceptorSpan = transactionEvent.spans.find(span => span.description === 'test-interceptor-span'); + const testInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'test-interceptor-span-after-route', + ); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'Interceptor - After Route' is the parent of 'test-interceptor-span-after-route' + expect(testInterceptorSpanAfterRoute.parent_span_id).toBe(exampleInterceptorSpanAfterRouteId); + + // 'Interceptor - After Route' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanAfterRouteId); +}); + +test('API route transaction includes nest async interceptor spans before route execution. Spans created in and after async interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('node-nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-async-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-async-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans before route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'AsyncInterceptor', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // get interceptor spans + const exampleAsyncInterceptor = transactionEvent.spans.find(span => span.description === 'AsyncInterceptor'); + const exampleAsyncInterceptorSpanId = exampleAsyncInterceptor?.span_id; + + // check if manually started spans exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-controller-span', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-async-interceptor-span', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testAsyncInterceptorSpan = transactionEvent.spans.find( + span => span.description === 'test-async-interceptor-span', + ); + const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); + + // 'AsyncInterceptor' is the parent of 'test-async-interceptor-span' + expect(testAsyncInterceptorSpan.parent_span_id).toBe(exampleAsyncInterceptorSpanId); + + // 'AsyncInterceptor' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleAsyncInterceptorSpanId); +}); + +test('API route transaction includes exactly one nest async interceptor span after route execution. Spans created in controller and in async interceptor are nested correctly', async ({ + baseURL, +}) => { + const pageloadTransactionEventPromise = waitForTransaction('node-nestjs-basic', transactionEvent => { + return ( + transactionEvent?.contexts?.trace?.op === 'http.server' && + transactionEvent?.transaction === 'GET /test-async-interceptor-instrumentation' + ); + }); + + const response = await fetch(`${baseURL}/test-async-interceptor-instrumentation`); + expect(response.status).toBe(200); + + const transactionEvent = await pageloadTransactionEventPromise; + + // check if interceptor spans after route execution exist + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: { + 'sentry.op': 'middleware.nestjs', + 'sentry.origin': 'auto.middleware.nestjs', + }, + description: 'Interceptors - After Route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + op: 'middleware.nestjs', + origin: 'auto.middleware.nestjs', + }, + ]), + }), + ); + + // check that exactly one after route span is sent + const allInterceptorSpansAfterRoute = transactionEvent.spans.filter( + span => span.description === 'Interceptors - After Route', + ); + expect(allInterceptorSpansAfterRoute.length).toBe(1); + + // get interceptor span + const exampleInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'Interceptors - After Route', + ); + const exampleInterceptorSpanAfterRouteId = exampleInterceptorSpanAfterRoute?.span_id; + + // check if manually started span in interceptor after route exists + expect(transactionEvent).toEqual( + expect.objectContaining({ + spans: expect.arrayContaining([ + { + span_id: expect.any(String), + trace_id: expect.any(String), + data: expect.any(Object), + description: 'test-async-interceptor-span-after-route', + parent_span_id: expect.any(String), + start_timestamp: expect.any(Number), + timestamp: expect.any(Number), + status: 'ok', + origin: 'manual', + }, + ]), + }), + ); + + // verify correct span parent-child relationships + const testInterceptorSpanAfterRoute = transactionEvent.spans.find( + span => span.description === 'test-async-interceptor-span-after-route', + ); const testControllerSpan = transactionEvent.spans.find(span => span.description === 'test-controller-span'); - // 'ExampleInterceptor' is the parent of 'test-interceptor-span' - expect(testInterceptorSpan.parent_span_id).toBe(exampleInterceptorSpanId); + // 'Interceptor - After Route' is the parent of 'test-interceptor-span-after-route' + expect(testInterceptorSpanAfterRoute.parent_span_id).toBe(exampleInterceptorSpanAfterRouteId); - // 'ExampleInterceptor' is NOT the parent of 'test-controller-span' - expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanId); + // 'Interceptor - After Route' is NOT the parent of 'test-controller-span' + expect(testControllerSpan.parent_span_id).not.toBe(exampleInterceptorSpanAfterRouteId); }); diff --git a/packages/node/src/integrations/tracing/nest/helpers.ts b/packages/node/src/integrations/tracing/nest/helpers.ts index babf80022c1f..e2d3c4c573b9 100644 --- a/packages/node/src/integrations/tracing/nest/helpers.ts +++ b/packages/node/src/integrations/tracing/nest/helpers.ts @@ -1,6 +1,7 @@ -import { SEMANTIC_ATTRIBUTE_SENTRY_OP, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN } from '@sentry/core'; +import { SEMANTIC_ATTRIBUTE_SENTRY_OP, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN, withActiveSpan } from '@sentry/core'; +import type { Span } from '@sentry/types'; import { addNonEnumerableProperty } from '@sentry/utils'; -import type { CatchTarget, InjectableTarget } from './types'; +import type { CatchTarget, InjectableTarget, Observable, Subscription } from './types'; const sentryPatched = 'sentryPatched'; @@ -23,12 +24,32 @@ export function isPatched(target: InjectableTarget | CatchTarget): boolean { * Returns span options for nest middleware spans. */ // eslint-disable-next-line @typescript-eslint/explicit-function-return-type -export function getMiddlewareSpanOptions(target: InjectableTarget | CatchTarget) { +export function getMiddlewareSpanOptions(target: InjectableTarget | CatchTarget, name: string | undefined = undefined) { + const span_name = name ?? target.name; // fallback to class name if no name is provided + return { - name: target.name, + name: span_name, attributes: { [SEMANTIC_ATTRIBUTE_SENTRY_OP]: 'middleware.nestjs', [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.middleware.nestjs', }, }; } + +/** + * Adds instrumentation to a js observable and attaches the span to an active parent span. + */ +export function instrumentObservable(observable: Observable, activeSpan: Span | undefined): void { + if (activeSpan) { + // eslint-disable-next-line @typescript-eslint/unbound-method + observable.subscribe = new Proxy(observable.subscribe, { + apply: (originalSubscribe, thisArgSubscribe, argsSubscribe) => { + return withActiveSpan(activeSpan, () => { + const subscription: Subscription = originalSubscribe.apply(thisArgSubscribe, argsSubscribe); + subscription.add(() => activeSpan.end()); + return subscription; + }); + }, + }); + } +} diff --git a/packages/node/src/integrations/tracing/nest/sentry-nest-instrumentation.ts b/packages/node/src/integrations/tracing/nest/sentry-nest-instrumentation.ts index a8d02e5cbe69..b8ea782ee66f 100644 --- a/packages/node/src/integrations/tracing/nest/sentry-nest-instrumentation.ts +++ b/packages/node/src/integrations/tracing/nest/sentry-nest-instrumentation.ts @@ -5,11 +5,11 @@ import { InstrumentationNodeModuleDefinition, InstrumentationNodeModuleFile, } from '@opentelemetry/instrumentation'; -import { getActiveSpan, startSpan, startSpanManual, withActiveSpan } from '@sentry/core'; +import { getActiveSpan, startInactiveSpan, startSpan, startSpanManual, withActiveSpan } from '@sentry/core'; import type { Span } from '@sentry/types'; -import { SDK_VERSION } from '@sentry/utils'; -import { getMiddlewareSpanOptions, isPatched } from './helpers'; -import type { CatchTarget, InjectableTarget } from './types'; +import { SDK_VERSION, addNonEnumerableProperty, isThenable } from '@sentry/utils'; +import { getMiddlewareSpanOptions, instrumentObservable, isPatched } from './helpers'; +import type { CallHandler, CatchTarget, InjectableTarget, MinimalNestJsExecutionContext, Observable } from './types'; const supportedVersions = ['>=8.0.0 <11']; @@ -163,33 +163,79 @@ export class SentryNestInstrumentation extends InstrumentationBase { target.prototype.intercept = new Proxy(target.prototype.intercept, { apply: (originalIntercept, thisArgIntercept, argsIntercept) => { - const [executionContext, next, args] = argsIntercept; - const prevSpan = getActiveSpan(); + const context: MinimalNestJsExecutionContext = argsIntercept[0]; + const next: CallHandler = argsIntercept[1]; - return startSpanManual(getMiddlewareSpanOptions(target), (span: Span) => { - const nextProxy = new Proxy(next, { - get: (thisArgNext, property, receiver) => { - if (property === 'handle') { - const originalHandle = Reflect.get(thisArgNext, property, receiver); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - return (...args: any[]) => { - span.end(); - - if (prevSpan) { - return withActiveSpan(prevSpan, () => { - return Reflect.apply(originalHandle, thisArgNext, args); - }); - } else { - return Reflect.apply(originalHandle, thisArgNext, args); + const parentSpan = getActiveSpan(); + let afterSpan: Span; + + return startSpanManual(getMiddlewareSpanOptions(target), (beforeSpan: Span) => { + // eslint-disable-next-line @typescript-eslint/unbound-method + next.handle = new Proxy(next.handle, { + apply: (originalHandle, thisArgHandle, argsHandle) => { + beforeSpan.end(); + + if (parentSpan) { + return withActiveSpan(parentSpan, () => { + const handleReturnObservable = Reflect.apply(originalHandle, thisArgHandle, argsHandle); + + if (!context._sentryInterceptorInstrumented) { + addNonEnumerableProperty(context, '_sentryInterceptorInstrumented', true); + afterSpan = startInactiveSpan( + getMiddlewareSpanOptions(target, 'Interceptors - After Route'), + ); } - }; - } - return Reflect.get(target, property, receiver); + return handleReturnObservable; + }); + } else { + const handleReturnObservable = Reflect.apply(originalHandle, thisArgHandle, argsHandle); + + if (!context._sentryInterceptorInstrumented) { + addNonEnumerableProperty(context, '_sentryInterceptorInstrumented', true); + afterSpan = startInactiveSpan(getMiddlewareSpanOptions(target, 'Interceptors - After Route')); + } + + return handleReturnObservable; + } }, }); - return originalIntercept.apply(thisArgIntercept, [executionContext, nextProxy, args]); + let returnedObservableInterceptMaybePromise: Observable | Promise>; + + try { + returnedObservableInterceptMaybePromise = originalIntercept.apply(thisArgIntercept, argsIntercept); + } catch (e) { + beforeSpan?.end(); + afterSpan?.end(); + throw e; + } + + if (!afterSpan) { + return returnedObservableInterceptMaybePromise; + } + + // handle async interceptor + if (isThenable(returnedObservableInterceptMaybePromise)) { + return returnedObservableInterceptMaybePromise.then( + observable => { + instrumentObservable(observable, afterSpan ?? parentSpan); + return observable; + }, + e => { + beforeSpan?.end(); + afterSpan?.end(); + throw e; + }, + ); + } + + // handle sync interceptor + if (typeof returnedObservableInterceptMaybePromise.subscribe === 'function') { + instrumentObservable(returnedObservableInterceptMaybePromise, afterSpan ?? parentSpan); + } + + return returnedObservableInterceptMaybePromise; }); }, }); diff --git a/packages/node/src/integrations/tracing/nest/types.ts b/packages/node/src/integrations/tracing/nest/types.ts index 42aa0b003315..18bd26b31ccb 100644 --- a/packages/node/src/integrations/tracing/nest/types.ts +++ b/packages/node/src/integrations/tracing/nest/types.ts @@ -1,6 +1,6 @@ /* eslint-disable @typescript-eslint/no-explicit-any */ -interface MinimalNestJsExecutionContext { +export interface MinimalNestJsExecutionContext { getType: () => string; switchToHttp: () => { @@ -14,6 +14,8 @@ interface MinimalNestJsExecutionContext { method?: string; }; }; + + _sentryInterceptorInstrumented?: boolean; } export interface NestJsErrorFilter { @@ -27,11 +29,15 @@ export interface MinimalNestJsApp { }) => void; } +export interface Subscription { + add(...args: any[]): void; +} + /** * A minimal interface for an Observable. */ export interface Observable { - subscribe(observer: (value: T) => void): void; + subscribe(next?: (value: T) => void, error?: (err: any) => void, complete?: () => void): Subscription; } /**