diff --git a/dev-packages/node-integration-tests/suites/vercel/instrument-withoutSpans.mjs b/dev-packages/node-integration-tests/suites/vercel/instrument-withoutSpans.mjs new file mode 100644 index 000000000000..0b7293bbafad --- /dev/null +++ b/dev-packages/node-integration-tests/suites/vercel/instrument-withoutSpans.mjs @@ -0,0 +1,17 @@ +import * as Sentry from '@sentry/node'; +import { loggingTransport } from '@sentry-internal/node-integration-tests'; + +process.env.VERCEL = 'true'; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + release: '1.0', + transport: loggingTransport, + // We look at debug logs in this test + debug: true, + integrations: [ + Sentry.httpIntegration({ + spans: false, + }), + ], +}); diff --git a/dev-packages/node-integration-tests/suites/vercel/scenario-withoutSpans.mjs b/dev-packages/node-integration-tests/suites/vercel/scenario-withoutSpans.mjs new file mode 100644 index 000000000000..ffe412549bb1 --- /dev/null +++ b/dev-packages/node-integration-tests/suites/vercel/scenario-withoutSpans.mjs @@ -0,0 +1,13 @@ +import * as Sentry from '@sentry/node'; +import { startExpressServerAndSendPortToRunner } from '@sentry-internal/node-integration-tests'; +import express from 'express'; + +const app = express(); + +app.get('/test/error', () => { + throw new Error('test error'); +}); + +Sentry.setupExpressErrorHandler(app); + +startExpressServerAndSendPortToRunner(app); diff --git a/dev-packages/node-integration-tests/suites/vercel/scenario.mjs b/dev-packages/node-integration-tests/suites/vercel/scenario.mjs index b2ed413175df..5952ecc98662 100644 --- a/dev-packages/node-integration-tests/suites/vercel/scenario.mjs +++ b/dev-packages/node-integration-tests/suites/vercel/scenario.mjs @@ -8,6 +8,10 @@ app.get('/test/express', (_req, res) => { res.send({ response: 'response 1' }); }); +app.get('/test/error', () => { + throw new Error('test error'); +}); + Sentry.setupExpressErrorHandler(app); startExpressServerAndSendPortToRunner(app); diff --git a/dev-packages/node-integration-tests/suites/vercel/test.ts b/dev-packages/node-integration-tests/suites/vercel/test.ts index 4517d0eaf115..3a8bb4e076d3 100644 --- a/dev-packages/node-integration-tests/suites/vercel/test.ts +++ b/dev-packages/node-integration-tests/suites/vercel/test.ts @@ -1,13 +1,13 @@ import { afterAll, describe, expect } from 'vitest'; import { cleanupChildProcesses, createEsmAndCjsTests } from '../../utils/runner'; -describe('vercel xxx', () => { +describe('vercel', () => { afterAll(() => { cleanupChildProcesses(); }); createEsmAndCjsTests(__dirname, 'scenario.mjs', 'instrument.mjs', (createRunner, test) => { - test('should flush events correctly on Vercel', async () => { + test('should flush spans correctly on Vercel', async () => { const runner = createRunner() .expect({ transaction: { @@ -47,7 +47,134 @@ describe('vercel xxx', () => { } } - expect(expectedLogs).toEqual([]); + if (expectedLogs.length > 0) { + // eslint-disable-next-line no-console + console.log(actualLogs); + expect(expectedLogs).toEqual([]); + } + }); + + test('should flush errors correctly on Vercel', async () => { + const runner = createRunner() + .expect({ + transaction: { + transaction: 'GET /test/error', + }, + }) + .expect({ + event: { + transaction: 'GET /test/error', + exception: { + values: [ + { + value: 'test error', + }, + ], + }, + }, + }) + .start(); + runner.makeRequest('get', '/test/error', { expectError: true }); + await runner.completed(); + + const actualLogs = runner.getLogs(); + + // We want to test that the following logs are present in this order + // other logs may be in between + const expectedLogs = [ + 'Sentry Logger [log]: @sentry/instrumentation-http Patching server.emit', + 'Sentry Logger [log]: @sentry/instrumentation-http Handling incoming request', + 'Sentry Logger [log]: @sentry/instrumentation-http Patching request.on', + 'Sentry Logger [debug]: @opentelemetry_sentry-patched/instrumentation-http http instrumentation incomingRequest', + 'Sentry Logger [log]: [Tracing] Starting sampled root span', + // later... + 'Sentry Logger [log]: Patching response to flush on Vercel', + 'Sentry Logger [log]: Patching res.end()', + // later... + 'Sentry Logger [log]: Captured error event `test error`', + // later... + 'Sentry Logger [log]: Flushing events before Vercel Lambda freeze', + 'Sentry Logger [log]: SpanExporter exported 4 spans, 0 spans are waiting for their parent spans to finish', + ]; + + // Test that the order of logs is correct + for (const log of actualLogs) { + if (expectedLogs.length === 0) { + break; + } + + if (log === expectedLogs[0]) { + expectedLogs.shift(); + } + } + + if (expectedLogs.length > 0) { + // eslint-disable-next-line no-console + console.log(actualLogs); + expect(expectedLogs).toEqual([]); + } }); }); + + describe('without http.server spans', () => { + createEsmAndCjsTests( + __dirname, + 'scenario-withoutSpans.mjs', + 'instrument-withoutSpans.mjs', + (createRunner, test) => { + test('should flush errors correctly on Vercel even without HTTP span instrumentation', async () => { + const runner = createRunner() + .expect({ + event: { + transaction: 'GET /test/error', + exception: { + values: [ + { + value: 'test error', + }, + ], + }, + }, + }) + .start(); + runner.makeRequest('get', '/test/error', { expectError: true }); + await runner.completed(); + + const actualLogs = runner.getLogs(); + + // We want to test that the following logs are present in this order + // other logs may be in between + const expectedLogs = [ + 'Sentry Logger [log]: @sentry/instrumentation-http Patching server.emit', + 'Sentry Logger [log]: Patching response to flush on Vercel', + 'Sentry Logger [log]: Patching res.end()', + 'Sentry Logger [log]: @sentry/instrumentation-http Handling incoming request', + 'Sentry Logger [log]: @sentry/instrumentation-http Patching request.on', + // later... + 'Sentry Logger [log]: Captured error event `test error`', + // later... + 'Sentry Logger [log]: Flushing events before Vercel Lambda freeze', + 'Sentry Logger [log]: SpanExporter exported 0 spans, 0 spans are waiting for their parent spans to finish', + ]; + + // Test that the order of logs is correct + for (const log of actualLogs) { + if (expectedLogs.length === 0) { + break; + } + + if (log === expectedLogs[0]) { + expectedLogs.shift(); + } + } + + if (expectedLogs.length > 0) { + // eslint-disable-next-line no-console + console.log(actualLogs); + expect(expectedLogs).toEqual([]); + } + }); + }, + ); + }); }); diff --git a/packages/node/src/integrations/http/SentryHttpInstrumentation.ts b/packages/node/src/integrations/http/SentryHttpInstrumentation.ts index 4e044879d2aa..fdd08e3a6672 100644 --- a/packages/node/src/integrations/http/SentryHttpInstrumentation.ts +++ b/packages/node/src/integrations/http/SentryHttpInstrumentation.ts @@ -12,6 +12,7 @@ import type { AggregationCounts, Client, SanitizedRequestData, Scope } from '@se import { addBreadcrumb, addNonEnumerableProperty, + flush, generateSpanId, getBreadcrumbLogLevelFromHttpStatusCode, getClient, @@ -22,6 +23,7 @@ import { logger, parseUrl, stripUrlQueryAndFragment, + vercelWaitUntil, withIsolationScope, } from '@sentry/core'; import { DEBUG_BUILD } from '../../debug-build'; @@ -49,6 +51,15 @@ export type SentryHttpInstrumentationOptions = InstrumentationConfig & { */ extractIncomingTraceFromHeader?: boolean; + /** + * If this is true, we try to patch the server response to ensure we flush on serverless platforms. + * For now, this is only the case when running on Vercel and when the OTEL Http instrumentation is not added, + * as otherwise that takes care of this (with slightly different timing mechanics). + * + * @default `false` + */ + patchResponseForServerless?: boolean; + /** * Do not capture breadcrumbs for outgoing HTTP requests to URLs where the given callback returns `true`. * For the scope of this instrumentation, this callback only controls breadcrumb creation. @@ -112,9 +123,15 @@ export class SentryHttpInstrumentation extends InstrumentationBase { - const data = _data as { server: http.Server }; + const data = _data as { server: http.Server; response: http.ServerResponse }; this._patchServerEmitOnce(data.server); + + if (patchResponseForServerless) { + patchResponseToFlushOnServerlessPlatformsOnce(data.response); + } }) satisfies ChannelListener; const onHttpClientResponseFinish = ((_data: unknown) => { @@ -127,6 +144,29 @@ export class SentryHttpInstrumentation extends InstrumentationBase(moduleExports: T): T => { + if (hasRegisteredHandlers) { + return moduleExports; + } + + hasRegisteredHandlers = true; + + subscribe('http.server.request.start', onHttpServerRequestStart); + subscribe('http.client.response.finish', onHttpClientResponseFinish); + + // When an error happens, we still want to have a breadcrumb + // In this case, `http.client.response.finish` is not triggered + subscribe('http.client.request.error', onHttpClientRequestError); + + return moduleExports; + }; + + const unregisterHandlers = (): void => { + unsubscribe('http.server.request.start', onHttpServerRequestStart); + unsubscribe('http.client.response.finish', onHttpClientResponseFinish); + unsubscribe('http.client.request.error', onHttpClientRequestError); + }; + /** * You may be wondering why we register these diagnostics-channel listeners * in such a convoluted way (as InstrumentationNodeModuleDefinition...)˝, @@ -136,56 +176,8 @@ export class SentryHttpInstrumentation extends InstrumentationBase { - if (hasRegisteredHandlers) { - return moduleExports; - } - - hasRegisteredHandlers = true; - - subscribe('http.server.request.start', onHttpServerRequestStart); - subscribe('http.client.response.finish', onHttpClientResponseFinish); - - // When an error happens, we still want to have a breadcrumb - // In this case, `http.client.response.finish` is not triggered - subscribe('http.client.request.error', onHttpClientRequestError); - - return moduleExports; - }, - () => { - unsubscribe('http.server.request.start', onHttpServerRequestStart); - unsubscribe('http.client.response.finish', onHttpClientResponseFinish); - unsubscribe('http.client.request.error', onHttpClientRequestError); - }, - ), - new InstrumentationNodeModuleDefinition( - 'https', - ['*'], - (moduleExports: Https): Https => { - if (hasRegisteredHandlers) { - return moduleExports; - } - - hasRegisteredHandlers = true; - - subscribe('http.server.request.start', onHttpServerRequestStart); - subscribe('http.client.response.finish', onHttpClientResponseFinish); - - // When an error happens, we still want to have a breadcrumb - // In this case, `http.client.response.finish` is not triggered - subscribe('http.client.request.error', onHttpClientRequestError); - - return moduleExports; - }, - () => { - unsubscribe('http.server.request.start', onHttpServerRequestStart); - unsubscribe('http.client.response.finish', onHttpClientResponseFinish); - unsubscribe('http.client.request.error', onHttpClientRequestError); - }, - ), + new InstrumentationNodeModuleDefinition('http', ['*'], registerHandlers, unregisterHandlers), + new InstrumentationNodeModuleDefinition('https', ['*'], registerHandlers, unregisterHandlers), ]; } @@ -529,6 +521,75 @@ export function recordRequestSession({ }); } +/** Ensure this is patched once. */ +export function patchResponseToFlushOnServerlessPlatformsOnce(res: http.ServerResponse): void { + // This means it was already patched, do nothing + if ((res as { __sentry_patched__?: boolean }).__sentry_patched__) { + return; + } + + // For now, only patch on Vercel + if (!process.env.VERCEL) { + return; + } + + addNonEnumerableProperty(res, '__sentry_patched__', true); + + // This is vercel specific handling to flush events before the lambda freezes + DEBUG_BUILD && logger.log('Patching response to flush on Vercel'); + + // In some cases res.end does not seem to be defined leading to errors if passed to Proxy + // https://github.com/getsentry/sentry-javascript/issues/15759 + if (typeof res.end !== 'function') { + DEBUG_BUILD && logger.warn('res.end is not a function, skipping patch...'); + return; + } + + let markOnEndDone = (): void => undefined; + const onEndDonePromise = new Promise(res => { + markOnEndDone = res; + }); + + res.on('close', () => { + markOnEndDone(); + }); + + logger.log('Patching res.end()'); + + // eslint-disable-next-line @typescript-eslint/unbound-method + res.end = new Proxy(res.end, { + apply(target, thisArg, argArray) { + vercelWaitUntil( + new Promise(finishWaitUntil => { + // Define a timeout that unblocks the lambda just to be safe so we're not indefinitely keeping it alive, exploding server bills + const timeout = setTimeout(() => { + finishWaitUntil(); + }, 2000); + + onEndDonePromise + .then(() => { + DEBUG_BUILD && logger.log('Flushing events before Vercel Lambda freeze'); + return flush(2000); + }) + .then( + () => { + clearTimeout(timeout); + finishWaitUntil(); + }, + e => { + clearTimeout(timeout); + DEBUG_BUILD && logger.log('Error while flushing events for Vercel:\n', e); + finishWaitUntil(); + }, + ); + }), + ); + + return target.apply(thisArg, argArray); + }, + }); +} + const clientToRequestSessionAggregatesMap = new Map< Client, { [timestampRoundedToSeconds: string]: { exited: number; crashed: number; errored: number } } diff --git a/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts b/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts deleted file mode 100644 index ace8cbfb4399..000000000000 --- a/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts +++ /dev/null @@ -1,136 +0,0 @@ -import type * as http from 'node:http'; -import type * as https from 'node:https'; -import { VERSION } from '@opentelemetry/core'; -import { InstrumentationBase, InstrumentationNodeModuleDefinition } from '@opentelemetry/instrumentation'; -import { flush, logger, vercelWaitUntil } from '@sentry/core'; -import { DEBUG_BUILD } from '../../debug-build'; -import { stealthWrap } from './utils'; - -type Http = typeof http; -type Https = typeof https; - -// The reason this "before OTEL" integration even exists is due to timing reasons. We need to be able to register a -// `res.on('close')` handler **after** OTEL registers its own handler (which it uses to end spans), so that we can do -// something (ie. flush) after OTEL has ended a span for a request. If you think about it like an onion: -// -// (Sentry after OTEL instrumentation -// (OTEL instrumentation -// (Sentry before OTEL instrumentation -// (orig HTTP request handler)))) -// -// registering an instrumentation before OTEL allows us to do this for incoming requests. - -/** - * A Sentry specific http instrumentation that is applied before the otel instrumentation. - */ -export class SentryHttpInstrumentationBeforeOtel extends InstrumentationBase { - public constructor() { - super('@sentry/instrumentation-http-before-otel', VERSION, {}); - } - - // eslint-disable-next-line jsdoc/require-jsdoc - public init(): [InstrumentationNodeModuleDefinition, InstrumentationNodeModuleDefinition] { - return [this._getHttpsInstrumentation(), this._getHttpInstrumentation()]; - } - - /** Get the instrumentation for the http module. */ - private _getHttpInstrumentation(): InstrumentationNodeModuleDefinition { - return new InstrumentationNodeModuleDefinition('http', ['*'], (moduleExports: Http): Http => { - // Patch incoming requests - stealthWrap(moduleExports.Server.prototype, 'emit', this._getPatchIncomingRequestFunction()); - - return moduleExports; - }); - } - - /** Get the instrumentation for the https module. */ - private _getHttpsInstrumentation(): InstrumentationNodeModuleDefinition { - return new InstrumentationNodeModuleDefinition('https', ['*'], (moduleExports: Https): Https => { - // Patch incoming requests - stealthWrap(moduleExports.Server.prototype, 'emit', this._getPatchIncomingRequestFunction()); - - return moduleExports; - }); - } - - /** - * Patch the incoming request function for request isolation. - */ - private _getPatchIncomingRequestFunction(): ( - original: (event: string, ...args: unknown[]) => boolean, - ) => (this: unknown, event: string, ...args: unknown[]) => boolean { - return ( - original: (event: string, ...args: unknown[]) => boolean, - ): ((this: unknown, event: string, ...args: unknown[]) => boolean) => { - return function incomingRequest(this: unknown, ...args: [event: string, ...args: unknown[]]): boolean { - // Only traces request events - if (args[0] !== 'request') { - return original.apply(this, args); - } - - const response = args[2] as http.OutgoingMessage; - patchResponseToFlushOnServerlessPlatforms(response); - - return original.apply(this, args); - }; - }; - } -} - -function patchResponseToFlushOnServerlessPlatforms(res: http.OutgoingMessage): void { - // Freely extend this function with other platforms if necessary - if (process.env.VERCEL) { - DEBUG_BUILD && logger.log('Patching response to flush on Vercel'); - - // In some cases res.end does not seem to be defined leading to errors if passed to Proxy - // https://github.com/getsentry/sentry-javascript/issues/15759 - if (typeof res.end !== 'function') { - DEBUG_BUILD && logger.warn('res.end is not a function, skipping patch...'); - return; - } - - let markOnEndDone = (): void => undefined; - const onEndDonePromise = new Promise(res => { - markOnEndDone = res; - }); - - res.on('close', () => { - markOnEndDone(); - }); - - logger.log('Patching res.end()'); - - // eslint-disable-next-line @typescript-eslint/unbound-method - res.end = new Proxy(res.end, { - apply(target, thisArg, argArray) { - vercelWaitUntil( - new Promise(finishWaitUntil => { - // Define a timeout that unblocks the lambda just to be safe so we're not indefinitely keeping it alive, exploding server bills - const timeout = setTimeout(() => { - finishWaitUntil(); - }, 2000); - - onEndDonePromise - .then(() => { - DEBUG_BUILD && logger.log('Flushing events before Vercel Lambda freeze'); - return flush(2000); - }) - .then( - () => { - clearTimeout(timeout); - finishWaitUntil(); - }, - e => { - clearTimeout(timeout); - DEBUG_BUILD && logger.log('Error while flushing events for Vercel:\n', e); - finishWaitUntil(); - }, - ); - }), - ); - - return target.apply(thisArg, argArray); - }, - }); - } -} diff --git a/packages/node/src/integrations/http/index.ts b/packages/node/src/integrations/http/index.ts index 9fe4792e12a3..b327fe21b4db 100644 --- a/packages/node/src/integrations/http/index.ts +++ b/packages/node/src/integrations/http/index.ts @@ -11,8 +11,7 @@ import type { NodeClientOptions } from '../../types'; import { addOriginToSpan } from '../../utils/addOriginToSpan'; import { getRequestUrl } from '../../utils/getRequestUrl'; import type { SentryHttpInstrumentationOptions } from './SentryHttpInstrumentation'; -import { SentryHttpInstrumentation } from './SentryHttpInstrumentation'; -import { SentryHttpInstrumentationBeforeOtel } from './SentryHttpInstrumentationBeforeOtel'; +import { patchResponseToFlushOnServerlessPlatformsOnce, SentryHttpInstrumentation } from './SentryHttpInstrumentation'; const INTEGRATION_NAME = 'Http'; @@ -108,10 +107,6 @@ interface HttpOptions { }; } -const instrumentSentryHttpBeforeOtel = generateInstrumentOnce(`${INTEGRATION_NAME}.sentry-before-otel`, () => { - return new SentryHttpInstrumentationBeforeOtel(); -}); - const instrumentSentryHttp = generateInstrumentOnce( `${INTEGRATION_NAME}.sentry`, options => { @@ -151,19 +146,6 @@ export const httpIntegration = defineIntegration((options: HttpOptions = {}) => return { name: INTEGRATION_NAME, setupOnce() { - // TODO: get rid of this too - // Below, we instrument the Node.js HTTP API three times. 2 times Sentry-specific, 1 time OTEL specific. - // Due to timing reasons, we sometimes need to apply Sentry instrumentation _before_ we apply the OTEL - // instrumentation (e.g. to flush on serverless platforms), and sometimes we need to apply Sentry instrumentation - // _after_ we apply OTEL instrumentation (e.g. for isolation scope handling and breadcrumbs). - - // This is Sentry-specific instrumentation that is applied _before_ any OTEL instrumentation. - if (process.env.VERCEL) { - // Currently this instrumentation only does something when deployed on Vercel, so to save some overhead, we short circuit adding it here only for Vercel. - // If it's functionality is extended in the future, feel free to remove the if statement and this comment. - instrumentSentryHttpBeforeOtel(); - } - const instrumentSpans = _shouldInstrumentSpans(options, getClient()?.getOptions()); // This is Sentry-specific instrumentation for request isolation and breadcrumbs @@ -172,6 +154,11 @@ export const httpIntegration = defineIntegration((options: HttpOptions = {}) => // If spans are not instrumented, it means the HttpInstrumentation has not been added // In that case, we want to handle incoming trace extraction ourselves extractIncomingTraceFromHeader: !instrumentSpans, + // On Vercel, we want to patch the response to flush on Vercel Lambda freeze + // This is usually done in the OTEL Http Instrumentation, but if that is not added, + // we do it here instead + // We also patch here if incoming request spans are disabled, as that means the relevant code is not run in the OTEL instrumentation + patchResponseForServerless: !!process.env.VERCEL && (!instrumentSpans || options.disableIncomingRequestSpans), }); // This is the "regular" OTEL instrumentation that emits spans @@ -192,6 +179,10 @@ function _isClientRequest(req: ClientRequest | HTTPModuleRequestIncomingMessage) return 'outputData' in req && 'outputSize' in req && !('client' in req) && !('statusCode' in req); } +function _isServerResponse(res: ServerResponse | HTTPModuleRequestIncomingMessage): res is ServerResponse { + return 'end' in res && typeof res.end === 'function'; +} + /** * Detects if an incoming request is a prefetch request. */ @@ -252,6 +243,13 @@ function getConfigWithDefaults(options: Partial = {}): HttpInstrume }, responseHook: (span, res) => { options.instrumentation?.responseHook?.(span, res); + + // We generally patch this in our SentryHttpInstrumentation, + // but the timing is slightly off there for us to ensure we capture the spans correctly + // So in addition to the general patching there, we also patch the response here to ensure the http.server spans are flushed correctly + if (process.env.VERCEL && _isServerResponse(res)) { + patchResponseToFlushOnServerlessPlatformsOnce(res); + } }, applyCustomAttributesOnSpan: ( span: Span,