From 92341fe486ececd9dd6a2d4c75f3bb5603ccf089 Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Mon, 4 Oct 2021 10:20:51 -0700 Subject: [PATCH 1/9] rename variables --- packages/nextjs/src/utils/withSentry.ts | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index 53ad6bf54931..7e89fd796ee8 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -10,7 +10,9 @@ const { parseRequest } = Handlers; // purely for clarity type WrappedNextApiHandler = NextApiHandler; -type AugmentedResponse = NextApiResponse & { __sentryTransaction?: Transaction }; +export type AugmentedNextApiResponse = NextApiResponse & { + __sentryTransaction?: Transaction; +}; // eslint-disable-next-line @typescript-eslint/explicit-module-boundary-types export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler => { @@ -69,7 +71,7 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler = // save a link to the transaction on the response, so that even if there's an error (landing us outside of // the domain), we can still finish it (albeit possibly missing some scope data) - (res as AugmentedResponse).__sentryTransaction = transaction; + (res as AugmentedNextApiResponse).__sentryTransaction = transaction; } } @@ -159,8 +161,8 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler = }; }; -type ResponseEndMethod = AugmentedResponse['end']; -type WrappedResponseEndMethod = AugmentedResponse['end']; +type ResponseEndMethod = AugmentedNextApiResponse['end']; +type WrappedResponseEndMethod = AugmentedNextApiResponse['end']; /** * Wrap `res.end()` so that it closes the transaction and flushes events before letting the request finish. @@ -173,7 +175,7 @@ type WrappedResponseEndMethod = AugmentedResponse['end']; * @returns The wrapped version */ function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod { - return async function newEnd(this: AugmentedResponse, ...args: unknown[]) { + return async function newEnd(this: AugmentedNextApiResponse, ...args: unknown[]) { const transaction = this.__sentryTransaction; if (transaction) { From 517f73e053769adbb60fcdb7bc4f8c7916fabd81 Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Mon, 8 Nov 2021 15:18:59 -0800 Subject: [PATCH 2/9] pull cleanup work out into its own function --- packages/nextjs/src/utils/withSentry.ts | 59 ++++++++++++++----------- 1 file changed, 34 insertions(+), 25 deletions(-) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index 7e89fd796ee8..5e16bda5dfc5 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -176,31 +176,7 @@ type WrappedResponseEndMethod = AugmentedNextApiResponse['end']; */ function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod { return async function newEnd(this: AugmentedNextApiResponse, ...args: unknown[]) { - const transaction = this.__sentryTransaction; - - if (transaction) { - transaction.setHttpStatus(this.statusCode); - - // Push `transaction.finish` to the next event loop so open spans have a better chance of finishing before the - // transaction closes, and make sure to wait until that's done before flushing events - const transactionFinished: Promise = new Promise(resolve => { - setImmediate(() => { - transaction.finish(); - resolve(); - }); - }); - await transactionFinished; - } - - // flush the event queue to ensure that events get sent to Sentry before the response is finished and the lambda - // ends - try { - logger.log('Flushing events...'); - await flush(2000); - logger.log('Done flushing events'); - } catch (e) { - logger.log(`Error while flushing events:\n${e}`); - } + await finishSentryProcessing(this); // If the request didn't error, we will have temporarily marked the response finished to avoid a nextjs warning // message. (See long note above.) Now we need to flip `finished` back to `false` so that the real `res.end()` @@ -210,3 +186,36 @@ function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod { return origEnd.call(this, ...args); }; } + +/** + * Close the open transaction (if any) and flush events to Sentry. + * + * @param res The outgoing response for this request, on which the transaction is stored + */ +async function finishSentryProcessing(res: AugmentedNextApiResponse): Promise { + const { __sentryTransaction: transaction } = res; + + if (transaction) { + transaction.setHttpStatus(res.statusCode); + + // Push `transaction.finish` to the next event loop so open spans have a better chance of finishing before the + // transaction closes, and make sure to wait until that's done before flushing events + const transactionFinished: Promise = new Promise(resolve => { + setImmediate(() => { + transaction.finish(); + resolve(); + }); + }); + await transactionFinished; + } + + // Flush the event queue to ensure that events get sent to Sentry before the response is finished and the lambda + // ends. If there was an error, rethrow it so that the normal exception-handling mechanisms can apply. + try { + logger.log('Flushing events...'); + await flush(2000); + logger.log('Done flushing events'); + } catch (e) { + logger.log(`Error while flushing events:\n${e}`); + } +} From 4702da73e9881f449f64baadec91b558c7e37c00 Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Mon, 8 Nov 2021 15:20:23 -0800 Subject: [PATCH 3/9] stop awaiting result of domain-bound handler --- packages/nextjs/src/utils/withSentry.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index 5e16bda5dfc5..d52d1dcbf39b 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -157,7 +157,9 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler = } }); - return await boundHandler(); + // Since API route handlers are all async, nextjs always awaits the return value (meaning it's fine for us to return + // a promise here rather than a real result, and it saves us the overhead of an `await` call.) + return boundHandler(); }; }; From 68aa490f508244e1df92b26394f3767aeb6c02a2 Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Mon, 8 Nov 2021 15:21:02 -0800 Subject: [PATCH 4/9] also flush before rethrowing error --- packages/nextjs/src/utils/withSentry.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index d52d1dcbf39b..39cd8811c934 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -150,6 +150,12 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler = captureException(objectifiedErr); } + // Make sure we have a chance to finish the transaction and flush events to Sentry before the handler errors + // out. (Apps which are deployed on Vercel run their API routes in lambdas, and those lambdas will shut down the + // moment they detect an error, so it's important to get this done before rethrowing the error. Apps not + // deployed serverlessly will run into this cleanup function again in `res.end(), but it'll just no-op.) + await finishSentryProcessing(res); + // We rethrow here so that nextjs can do with the error whatever it would normally do. (Sometimes "whatever it // would normally do" is to allow the error to bubble up to the global handlers - another reason we need to mark // the error as already having been captured.) From ec6822dd434637ad2322441149cacda383556a6d Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Mon, 8 Nov 2021 15:21:33 -0800 Subject: [PATCH 5/9] manually set error status on response --- packages/nextjs/src/utils/withSentry.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index 39cd8811c934..1e80f5e903c7 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -150,6 +150,12 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler = captureException(objectifiedErr); } + // Because we're going to finish and send the transaction before passing the error onto nextjs, it won't yet + // have had a chance to set the status to 500, so unless we do it ourselves now, we'll incorrectly report that + // the transaction was error-free + res.statusCode = 500; + res.statusMessage = 'Internal Server Error'; + // Make sure we have a chance to finish the transaction and flush events to Sentry before the handler errors // out. (Apps which are deployed on Vercel run their API routes in lambdas, and those lambdas will shut down the // moment they detect an error, so it's important to get this done before rethrowing the error. Apps not From 87efd29d0f112b377130dfae27883c568dad5e6e Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Tue, 9 Nov 2021 06:24:30 -0800 Subject: [PATCH 6/9] fix wrapped handler type --- packages/nextjs/src/utils/withSentry.ts | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/packages/nextjs/src/utils/withSentry.ts b/packages/nextjs/src/utils/withSentry.ts index 1e80f5e903c7..f30234474c25 100644 --- a/packages/nextjs/src/utils/withSentry.ts +++ b/packages/nextjs/src/utils/withSentry.ts @@ -3,12 +3,13 @@ import { extractTraceparentData, hasTracingEnabled } from '@sentry/tracing'; import { Transaction } from '@sentry/types'; import { addExceptionMechanism, isString, logger, objectify, stripUrlQueryAndFragment } from '@sentry/utils'; import * as domain from 'domain'; -import { NextApiHandler, NextApiResponse } from 'next'; +import { NextApiHandler, NextApiRequest, NextApiResponse } from 'next'; const { parseRequest } = Handlers; -// purely for clarity -type WrappedNextApiHandler = NextApiHandler; +// This is the same as the `NextApiHandler` type, except instead of having a return type of `void | Promise`, it's +// only `Promise`, because wrapped handlers are always async +export type WrappedNextApiHandler = (req: NextApiRequest, res: NextApiResponse) => Promise; export type AugmentedNextApiResponse = NextApiResponse & { __sentryTransaction?: Transaction; From da218b3c3d1636d44faadc97dfa4ba678efb5d92 Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Tue, 9 Nov 2021 06:19:45 -0800 Subject: [PATCH 7/9] add flushing tests --- packages/nextjs/test/utils/withSentry.test.ts | 92 +++++++++++++++++++ 1 file changed, 92 insertions(+) create mode 100644 packages/nextjs/test/utils/withSentry.test.ts diff --git a/packages/nextjs/test/utils/withSentry.test.ts b/packages/nextjs/test/utils/withSentry.test.ts new file mode 100644 index 000000000000..3efe8afc09cd --- /dev/null +++ b/packages/nextjs/test/utils/withSentry.test.ts @@ -0,0 +1,92 @@ +import * as Sentry from '@sentry/node'; +import * as utils from '@sentry/utils'; +import { NextApiHandler, NextApiRequest, NextApiResponse } from 'next'; + +import { AugmentedNextApiResponse, withSentry, WrappedNextApiHandler } from '../../src/utils/withSentry'; + +const FLUSH_DURATION = 200; + +async function sleep(ms: number): Promise { + await new Promise(resolve => setTimeout(resolve, ms)); +} + +async function callWrappedHandler(wrappedHandler: WrappedNextApiHandler, req: NextApiRequest, res: NextApiResponse) { + await wrappedHandler(req, res); + + // Within the wrapped handler, we await `flush()` inside `res.end()`, but nothing awaits `res.end()`, because in its + // original version, it's sync (unlike the function we wrap around it). The original does actually *act* like an async + // function being awaited - subsequent steps in the request/response lifecycle don't happen until it emits a + // `prefinished` event (which is why it's safe for us to make the switch). But here in tests, there's nothing past + // `res.end()`, so we have to manually wait for it to be done. + await sleep(FLUSH_DURATION); + while (!res.finished) { + await sleep(100); + } +} + +// We mock `captureException` as a no-op because under normal circumstances it is an un-awaited effectively-async +// function which might or might not finish before any given test ends, potentially leading jest to error out. +const captureExceptionSpy = jest.spyOn(Sentry, 'captureException').mockImplementation(jest.fn()); +const loggerSpy = jest.spyOn(utils.logger, 'log'); +const flushSpy = jest.spyOn(Sentry, 'flush').mockImplementation(async () => { + // simulate the time it takes time to flush all events + await sleep(FLUSH_DURATION); + return true; +}); + +describe('withSentry', () => { + let req: NextApiRequest, res: NextApiResponse; + + const error = new Error('Oh, no! Charlie ate the flip-flops! :-('); + + const origHandlerNoError: NextApiHandler = async (_req, res) => { + res.send('Good dog, Maisey!'); + }; + const origHandlerWithError: NextApiHandler = async (_req, _res) => { + throw error; + }; + + const wrappedHandlerNoError = withSentry(origHandlerNoError); + const wrappedHandlerWithError = withSentry(origHandlerWithError); + + beforeEach(() => { + req = { url: 'http://dogs.are.great' } as NextApiRequest; + res = ({ + send: function(this: AugmentedNextApiResponse) { + this.end(); + }, + end: function(this: AugmentedNextApiResponse) { + this.finished = true; + }, + } as unknown) as AugmentedNextApiResponse; + }); + + afterEach(() => { + jest.clearAllMocks(); + }); + + describe('flushing', () => { + it('flushes events before rethrowing error', async () => { + try { + await callWrappedHandler(wrappedHandlerWithError, req, res); + } catch (err) { + expect(err).toBe(error); + } + + expect(captureExceptionSpy).toHaveBeenCalledWith(error); + expect(flushSpy).toHaveBeenCalled(); + expect(loggerSpy).toHaveBeenCalledWith('Done flushing events'); + + // This ensures the expect inside the `catch` block actually ran, i.e., that in the end the wrapped handler + // errored out the same way it would without sentry, meaning the error was indeed rethrown + expect.assertions(4); + }); + + it('flushes events before finishing non-erroring response', async () => { + await callWrappedHandler(wrappedHandlerNoError, req, res); + + expect(flushSpy).toHaveBeenCalled(); + expect(loggerSpy).toHaveBeenCalledWith('Done flushing events'); + }); + }); +}); From ed6d624cdcb6f46c9af8655624ff5ea5fd30435a Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Wed, 10 Nov 2021 16:12:52 -0800 Subject: [PATCH 8/9] rework comments in helper function to make it clear the loop ends --- packages/nextjs/test/utils/withSentry.test.ts | 22 ++++++++++++++----- 1 file changed, 16 insertions(+), 6 deletions(-) diff --git a/packages/nextjs/test/utils/withSentry.test.ts b/packages/nextjs/test/utils/withSentry.test.ts index 3efe8afc09cd..dfdc278000cd 100644 --- a/packages/nextjs/test/utils/withSentry.test.ts +++ b/packages/nextjs/test/utils/withSentry.test.ts @@ -9,16 +9,26 @@ const FLUSH_DURATION = 200; async function sleep(ms: number): Promise { await new Promise(resolve => setTimeout(resolve, ms)); } - +/** + * Helper to prevent tests from ending before `flush()` has finished its work. + * + * This is necessary because, like its real-life counterpart, our mocked `res.send()` below doesn't await `res.end() + * (which becomes async when we wrap it in `withSentry` in order to give `flush()` time to run). In real life, the + * request/response cycle is held open as subsequent steps wait for `end()` to emit its `prefinished` event. Here in + * tests, without any of that other machinery, we have to hold it open ourselves. + * + * @param wrappedHandler + * @param req + * @param res + */ async function callWrappedHandler(wrappedHandler: WrappedNextApiHandler, req: NextApiRequest, res: NextApiResponse) { await wrappedHandler(req, res); - // Within the wrapped handler, we await `flush()` inside `res.end()`, but nothing awaits `res.end()`, because in its - // original version, it's sync (unlike the function we wrap around it). The original does actually *act* like an async - // function being awaited - subsequent steps in the request/response lifecycle don't happen until it emits a - // `prefinished` event (which is why it's safe for us to make the switch). But here in tests, there's nothing past - // `res.end()`, so we have to manually wait for it to be done. + // we know we need to wait at least this long for `flush()` to finish await sleep(FLUSH_DURATION); + + // should be <1 second, just long enough the `flush()` call to return, the original (pre-wrapping) `res.end()` to be + // called, and the response to be marked as done while (!res.finished) { await sleep(100); } From 5c89c28fc9c42ea40bc267179862da9974ee39bc Mon Sep 17 00:00:00 2001 From: Katie Byers Date: Wed, 10 Nov 2021 16:13:25 -0800 Subject: [PATCH 9/9] give the thrown error a more distinctive name --- packages/nextjs/test/utils/withSentry.test.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/packages/nextjs/test/utils/withSentry.test.ts b/packages/nextjs/test/utils/withSentry.test.ts index dfdc278000cd..b8adfc7b592b 100644 --- a/packages/nextjs/test/utils/withSentry.test.ts +++ b/packages/nextjs/test/utils/withSentry.test.ts @@ -47,13 +47,13 @@ const flushSpy = jest.spyOn(Sentry, 'flush').mockImplementation(async () => { describe('withSentry', () => { let req: NextApiRequest, res: NextApiResponse; - const error = new Error('Oh, no! Charlie ate the flip-flops! :-('); + const noShoesError = new Error('Oh, no! Charlie ate the flip-flops! :-('); const origHandlerNoError: NextApiHandler = async (_req, res) => { res.send('Good dog, Maisey!'); }; const origHandlerWithError: NextApiHandler = async (_req, _res) => { - throw error; + throw noShoesError; }; const wrappedHandlerNoError = withSentry(origHandlerNoError); @@ -80,10 +80,10 @@ describe('withSentry', () => { try { await callWrappedHandler(wrappedHandlerWithError, req, res); } catch (err) { - expect(err).toBe(error); + expect(err).toBe(noShoesError); } - expect(captureExceptionSpy).toHaveBeenCalledWith(error); + expect(captureExceptionSpy).toHaveBeenCalledWith(noShoesError); expect(flushSpy).toHaveBeenCalled(); expect(loggerSpy).toHaveBeenCalledWith('Done flushing events');