From 04156623921cedf9e67ec2efcace3cbf83307052 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 6 May 2025 15:33:52 +0200 Subject: [PATCH] fix(node): Fix vercel flushing logic & add test for it --- .../suites/vercel/instrument.mjs | 13 +++ .../suites/vercel/scenario.mjs | 13 +++ .../suites/vercel/test.ts | 53 +++++++++++ .../SentryHttpInstrumentationBeforeOtel.ts | 94 ++++++++++--------- 4 files changed, 129 insertions(+), 44 deletions(-) create mode 100644 dev-packages/node-integration-tests/suites/vercel/instrument.mjs create mode 100644 dev-packages/node-integration-tests/suites/vercel/scenario.mjs create mode 100644 dev-packages/node-integration-tests/suites/vercel/test.ts diff --git a/dev-packages/node-integration-tests/suites/vercel/instrument.mjs b/dev-packages/node-integration-tests/suites/vercel/instrument.mjs new file mode 100644 index 000000000000..e3a1dbab7ba5 --- /dev/null +++ b/dev-packages/node-integration-tests/suites/vercel/instrument.mjs @@ -0,0 +1,13 @@ +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', + tracesSampleRate: 1.0, + transport: loggingTransport, + // We look at debug logs in this test + debug: true, +}); diff --git a/dev-packages/node-integration-tests/suites/vercel/scenario.mjs b/dev-packages/node-integration-tests/suites/vercel/scenario.mjs new file mode 100644 index 000000000000..b2ed413175df --- /dev/null +++ b/dev-packages/node-integration-tests/suites/vercel/scenario.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/express', (_req, res) => { + res.send({ response: 'response 1' }); +}); + +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 new file mode 100644 index 000000000000..4517d0eaf115 --- /dev/null +++ b/dev-packages/node-integration-tests/suites/vercel/test.ts @@ -0,0 +1,53 @@ +import { afterAll, describe, expect } from 'vitest'; +import { cleanupChildProcesses, createEsmAndCjsTests } from '../../utils/runner'; + +describe('vercel xxx', () => { + afterAll(() => { + cleanupChildProcesses(); + }); + + createEsmAndCjsTests(__dirname, 'scenario.mjs', 'instrument.mjs', (createRunner, test) => { + test('should flush events correctly on Vercel', async () => { + const runner = createRunner() + .expect({ + transaction: { + transaction: 'GET /test/express', + }, + }) + .start(); + runner.makeRequest('get', '/test/express'); + 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]: 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(); + } + } + + expect(expectedLogs).toEqual([]); + }); + }); +}); diff --git a/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts b/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts index e17194669eb0..ace8cbfb4399 100644 --- a/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts +++ b/packages/node/src/integrations/http/SentryHttpInstrumentationBeforeOtel.ts @@ -68,8 +68,7 @@ export class SentryHttpInstrumentationBeforeOtel extends InstrumentationBase { return original.apply(this, args); } - const response = args[1] as http.OutgoingMessage; - + const response = args[2] as http.OutgoingMessage; patchResponseToFlushOnServerlessPlatforms(response); return original.apply(this, args); @@ -81,50 +80,57 @@ export class SentryHttpInstrumentationBeforeOtel extends InstrumentationBase { 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') { - let markOnEndDone = (): void => undefined; - const onEndDonePromise = new Promise(res => { - markOnEndDone = res; - }); - - res.on('close', () => { - markOnEndDone(); - }); - - // 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); - }, - }); + 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); + }, + }); } }