fix(nextjs): Delay error propagation until withSentry is done (#4027)

In our nextjs API route wrapper `withSentry`, we capture any errors thrown by the original handler, and then once we've captured them, we rethrow them, so that our capturing of them doesn't interfere with whatever other error handling might go on. Until recently, that was fine, as nextjs didn't actually propagate the error any farther, and so it didn't interfere with our processing pipeline and didn't prevent `res.end()` (on which we rely for finishing the transaction and flushing events to Sentry) from running.

However, Vercel released a change[1] which caused said errors to begin propagating if the API route is running on Vercel. (Technically, it's if the server is running in minimal mode, but all API handlers on vercel do.) A side effect of this change is that when there's an error, `res.end()` is no longer called. As a result, the SDK's work is cut short, and neither errors in API route handlers nor transactions tracing such routes make it to Sentry.

This fixes that, by moving the work of finishing the transaction and flushing events into its own function and calling it not only in `res.end()` but also before we rethrow the error.

(Note: In the cases where there is an error and the server is not running in minimal mode, this means that function will be hit twice, but that's okay, since the second time around it will just no-op, since `transaction.finish()` bails immediately if the transaction is already finished, and `flush()` returns immediately if there's nothing to flush.)

H/t to @jmurty for his work in #4044, which helped me fix some problems in my first approach to solving this problem.

Fixes #3917.

[1] vercel/next.js#26875

Author: lobsterkatie

packages/nextjs/src/utils/withSentry.ts

@@ -3,14 +3,17 @@ 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<void>`, it's
+// only `Promise<void>`, because wrapped handlers are always async
+export type WrappedNextApiHandler = (req: NextApiRequest, res: NextApiResponse) => Promise<void>;
 
-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 +72,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;
         }
       }
 
@@ -148,19 +151,33 @@ 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
+        // 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.)
         throw objectifiedErr;
       }
     });
 
-    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();
   };
 };
 
-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,32 +190,8 @@ type WrappedResponseEndMethod = AugmentedResponse['end'];
  * @returns The wrapped version
  */
 function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod {
-  return async function newEnd(this: AugmentedResponse, ...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<void> = 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}`);
-    }
+  return async function newEnd(this: AugmentedNextApiResponse, ...args: unknown[]) {
+    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()`
@@ -208,3 +201,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<void> {
+  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<void> = 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}`);
+  }
+}

packages/nextjs/test/utils/withSentry.test.ts

@@ -0,0 +1,102 @@
+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<void> {
+  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);
+
+  // 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);
+  }
+}
+
+// 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 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 noShoesError;
+  };
+
+  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(noShoesError);
+      }
+
+      expect(captureExceptionSpy).toHaveBeenCalledWith(noShoesError);
+      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');
+    });
+  });
+});