Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ref(nextjs): Use flush code from withSentry in all backend wrappers #5814

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
4 changes: 2 additions & 2 deletions packages/nextjs/src/config/wrappers/types.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import type { Transaction } from '@sentry/types';
import type { Transaction, WrappedFunction } from '@sentry/types';
import type { NextApiRequest, NextApiResponse } from 'next';

// The `NextApiHandler` and `WrappedNextApiHandler` types are the same as the official `NextApiHandler` type, except:
Expand Down Expand Up @@ -42,4 +42,4 @@ export type AugmentedNextApiResponse = NextApiResponse & {
};

export type ResponseEndMethod = AugmentedNextApiResponse['end'];
export type WrappedResponseEndMethod = AugmentedNextApiResponse['end'];
export type WrappedResponseEndMethod = AugmentedNextApiResponse['end'] & WrappedFunction;
69 changes: 69 additions & 0 deletions packages/nextjs/src/config/wrappers/utils/responseEnd.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,69 @@
import { flush } from '@sentry/node';
import { Transaction } from '@sentry/types';
import { fill, logger } from '@sentry/utils';
import { ServerResponse } from 'http';

import { ResponseEndMethod, WrappedResponseEndMethod } from '../types';

/**
* Wrap `res.end()` so that it closes the transaction and flushes events before letting the request finish.
*
* Note: This wraps a sync method with an async method. While in general that's not a great idea in terms of keeping
* things in the right order, in this case it's safe, because the native `.end()` actually *is* (effectively) async, and
* its run actually *is* (literally) awaited, just manually so (which reflects the fact that the core of the
* request/response code in Node by far predates the introduction of `async`/`await`). When `.end()` is done, it emits
* the `prefinish` event, and only once that fires does request processing continue. See
* https://github.com/nodejs/node/commit/7c9b607048f13741173d397795bac37707405ba7.
*
* Also note: `res.end()` isn't called until *after* all response data and headers have been sent, so blocking inside of
* `end` doesn't delay data getting to the end user. See
* https://nodejs.org/api/http.html#responseenddata-encoding-callback.
*
* @param transaction The transaction tracing request handling
* @param res: The request's corresponding response
*/
export function autoEndTransactionOnResponseEnd(transaction: Transaction, res: ServerResponse): void {
const wrapEndMethod = (origEnd: ResponseEndMethod): WrappedResponseEndMethod => {
return async function sentryWrappedEnd(this: ServerResponse, ...args: unknown[]) {
await finishTransaction(transaction, this);
await flushQueue();

return origEnd.call(this, ...args);
};
};

// Prevent double-wrapping
if (!(res.end as WrappedResponseEndMethod).__sentry_original__) {
Copy link
Member

@lforst lforst Sep 26, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Apparently res.end can be undefined. It crashes my deployment static pages with getInitialProps on _app.js:

Page:

const Home = ({ returnedProps }) => {
  return (
    <>
      <h1>Hello World!</h1>
      <p>{JSON.stringify(returnedProps)}</p>
      <input
        type={"button"}
        onClick={() => {
          throw new Error();
        }}
      />
    </>
  );
};

export const getStaticProps = async () => {
  console.log(`Called getStaticProps in hello-world.tsx`);
  return { props: { returnedProps: { hello: "world" } } };
};

export default Home;

_app:

import App from "next/app";
import Head from "next/head";
import { useRouter } from "next/router";
import { Nav } from "../components/nav";
import "../styles/globals.css";

const MyApp = ({ Component, pageProps }) => {
  const router = useRouter();
  return (
    <>
      <Head>
        <title>Next 12 example</title>
        <link rel="icon" href="/favicon.ico" />
      </Head>
      <Nav currentPath={router.asPath} />
      <Component {...pageProps} />
    </>
  );
};

MyApp.getInitialProps = async (appContext) => {
  // calls page's `getInitialProps` and fills `appProps.pageProps`
  const appProps = await App.getInitialProps(appContext);

  console.log("Called _app.tsx getInitialProps", {
    parameterizedRoute: appContext.ctx.pathname,
  });

  return { ...appProps };
};

export default MyApp;

Logs:

Error occurred prerendering page "/hello-world". Read more: https://nextjs.org/docs/messages/prerender-error
TypeError: Cannot read properties of undefined (reading '__sentry_original__')
    at Object.autoEndTransactionOnResponseEnd (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/utils/responseEnd.js:36:19)
    at /vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:92:19
    at bound (node:domain:421:15)
    at runBound (node:domain:432:12)
    at Object.callTracedServerSideDataFetcher (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:128:5)
    at Function.getInitialProps (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/withSentryServerSideAppGetInitialProps.js:34:23)
    at Object.<anonymous> (/vercel/path0/node_modules/next/dist/shared/lib/utils.js:75:33)
    at Generator.next (<anonymous>)
    at asyncGeneratorStep (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:23:28)
    at _next (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:12:17)
Sentry Logger [log]: [Tracing] starting nextjs.data.server transaction - /static-parameterized-page/[pageNum]
Sentry Logger [log]: [Tracing] starting nextjs.data.server transaction - /static-parameterized-page/[pageNum]
Error occurred prerendering page "/static-parameterized-page/two". Read more: https://nextjs.org/docs/messages/prerender-error
TypeError: Cannot read properties of undefined (reading '__sentry_original__')
    at Object.autoEndTransactionOnResponseEnd (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/utils/responseEnd.js:36:19)
    at /vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:92:19
    at bound (node:domain:421:15)
    at runBound (node:domain:432:12)
    at Object.callTracedServerSideDataFetcher (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:128:5)
    at Function.getInitialProps (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/withSentryServerSideAppGetInitialProps.js:34:23)
    at Object.<anonymous> (/vercel/path0/node_modules/next/dist/shared/lib/utils.js:75:33)
    at Generator.next (<anonymous>)
    at asyncGeneratorStep (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:23:28)
    at _next (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:12:17)
Error occurred prerendering page "/static-parameterized-page/one". Read more: https://nextjs.org/docs/messages/prerender-error
TypeError: Cannot read properties of undefined (reading '__sentry_original__')
    at Object.autoEndTransactionOnResponseEnd (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/utils/responseEnd.js:36:19)
    at /vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:92:19
    at bound (node:domain:421:15)
    at runBound (node:domain:432:12)
    at Object.callTracedServerSideDataFetcher (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/wrapperUtils.js:128:5)
    at Function.getInitialProps (/vercel/path0/node_modules/@sentry/nextjs/build/cjs/config/wrappers/withSentryServerSideAppGetInitialProps.js:34:23)
    at Object.<anonymous> (/vercel/path0/node_modules/next/dist/shared/lib/utils.js:75:33)
    at Generator.next (<anonymous>)
    at asyncGeneratorStep (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:23:28)
    at _next (/vercel/path0/node_modules/@swc/helpers/lib/_async_to_generator.js:12:17)
info  - Generating static pages (3/3)
> Build error occurred
Error: Export encountered errors on following paths:
	/hello-world
	/static-parameterized-page/[pageNum]: /static-parameterized-page/one
	/static-parameterized-page/[pageNum]: /static-parameterized-page/two
    at /vercel/path0/node_modules/next/dist/export/index.js:404:19
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Span.traceAsyncFn (/vercel/path0/node_modules/next/dist/trace/trace.js:79:20)
    at async /vercel/path0/node_modules/next/dist/build/index.js:1229:21
    at async Span.traceAsyncFn (/vercel/path0/node_modules/next/dist/trace/trace.js:79:20)
    at async /vercel/path0/node_modules/next/dist/build/index.js:1091:17
    at async Span.traceAsyncFn (/vercel/path0/node_modules/next/dist/trace/trace.js:79:20)
    at async Object.build [as default] (/vercel/path0/node_modules/next/dist/build/index.js:65:29)
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
Error: Command "yarn build:vercel" exited with 1

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Huh. What version of next are you using? Do you have anything special set in your next.config.js? I just used both of the above pages and neither my local build nor my vercel build broke, and I was able to visit the page both on localhost and my vercel deployment.

(I mean, I can check for res.end easily enough, but this is still confusing.)

UPDATE: Okay, something is wrong. Nextjs itself calls res.end() all over the place without checking that it exists - during build, during runtime for normal pages, and during runtime for API pages. If there were any possibility of it being undefined, it seems to me that would have backfired on them long ago.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P.S. Here are the links for my test:

_app: https://github.com/lobsterkatie/nextjs-test-app/blob/cb86d720feb791c9f869e13b57533be355f386e3/pages/_app.js
test page: https://github.com/lobsterkatie/nextjs-test-app/blob/cb86d720feb791c9f869e13b57533be355f386e3/pages/boring/lucaTest.js
deployed test page: https://nextjs-test-cyorm8xox-lobsterkatie.vercel.app/boring/lucaTest

Note that to be fair, I didn't use your exact _app page, because I don't have the Nav component, so I removed it. But I can't see how that changes anything with respect to end being defined (or not).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I know what is going on. In short: Our isBuild function is broken for anybody using a different build command than the default yarn build or next build (or as a matter of fact any command that has an isolated argument build in it).

In my vercel test setup I am using the command build:vercel for which the check process.argv.includes('build') fails. This is probably why it was working for me locally (where I use the build command yarn build) and failing on vercel - because locally the instrumentation wasn't used during build, but on vercel it was. I'll try to push a fix in a separate PR.

Anyhow, it still seems that during build .end might be undefined - maybe we're missing something in the Next codebase. Should we check for its existence before we assume its there or is this too edgecasey?

On a somewhat unrelated note: What I will definitely do is change our wrapping functions to not assume that req/res is always there. It seemed fine at first but this whole thing sketched me out a bit.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did discover in my testing that isBuild wasn't running on vercel at all, because the if in index.server.ts was short-circuiting. That fix is a one-liner, so lemme push that right now. The question of what to look for is a bigger one, which I can't test at the moment because suddenly my dev env can't find either node or yarn. 🤦🏻‍♀️ I can look at it tomorrow, though.

UPDATE: The first part is done in #5828.

fill(res, 'end', wrapEndMethod);
}
}

/** Finish the given response's transaction and set HTTP status data */
export async function finishTransaction(transaction: Transaction | undefined, res: ServerResponse): Promise<void> {
if (transaction) {
transaction.setHttpStatus(res.statusCode);

// If any open spans are set to finish when the response ends, it sets up a race condition between their `finish`
// calls and the transaction's `finish` call - and any spans which lose the race will get dropped from the
// transaction. To prevent this, push `transaction.finish` to the next event loop so that it's guaranteed to lose
// the race, and wait for it to be 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 */
export async function flushQueue(): Promise<void> {
try {
__DEBUG_BUILD__ && logger.log('Flushing events...');
await flush(2000);
__DEBUG_BUILD__ && logger.log('Done flushing events');
} catch (e) {
__DEBUG_BUILD__ && logger.log('Error while flushing events:\n', e);
}
}
84 changes: 10 additions & 74 deletions packages/nextjs/src/config/wrappers/withSentryAPI.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
import { captureException, flush, getCurrentHub, startTransaction } from '@sentry/node';
import { captureException, getCurrentHub, startTransaction } from '@sentry/node';
import { extractTraceparentData, hasTracingEnabled } from '@sentry/tracing';
import {
addExceptionMechanism,
Expand All @@ -11,14 +11,8 @@ import {
import * as domain from 'domain';

import { formatAsCode, nextLogger } from '../../utils/nextLogger';
import type {
AugmentedNextApiRequest,
AugmentedNextApiResponse,
NextApiHandler,
ResponseEndMethod,
WrappedNextApiHandler,
WrappedResponseEndMethod,
} from './types';
import type { AugmentedNextApiRequest, AugmentedNextApiResponse, NextApiHandler, WrappedNextApiHandler } from './types';
import { autoEndTransactionOnResponseEnd, finishTransaction, flushQueue } from './utils/responseEnd';

/**
* Wrap the given API route handler for tracing and error capturing. Thin wrapper around `withSentry`, which only
Expand Down Expand Up @@ -72,11 +66,6 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
}
req.__withSentry_applied__ = true;

// first order of business: monkeypatch `res.end()` so that it will wait for us to send events to sentry before it
// fires (if we don't do this, the lambda will close too early and events will be either delayed or lost)
// eslint-disable-next-line @typescript-eslint/unbound-method
res.end = wrapEndMethod(res.end);

// use a domain in order to prevent scope bleed between requests
const local = domain.create();
local.add(req);
Expand All @@ -86,6 +75,7 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
// return a value. In our case, all any of the codepaths return is a promise of `void`, but nextjs still counts on
// getting that before it will finish the response.
const boundHandler = local.bind(async () => {
let transaction;
const currentScope = getCurrentHub().getScope();

if (currentScope) {
Expand Down Expand Up @@ -121,7 +111,7 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str

const reqMethod = `${(req.method || 'GET').toUpperCase()} `;

const transaction = startTransaction(
transaction = startTransaction(
{
name: `${reqMethod}${reqPath}`,
op: 'http.server',
Expand All @@ -137,9 +127,7 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
);
currentScope.setSpan(transaction);

// 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.__sentryTransaction = transaction;
autoEndTransactionOnResponseEnd(transaction, res);
}
}

Expand Down Expand Up @@ -188,8 +176,10 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
// 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);
// deployed serverlessly will run into this cleanup code again in `res.end(), but the transaction will already
// be finished and the queue will already be empty, so effectively it'll just no-op.)
await finishTransaction(transaction, res);
await flushQueue();

// 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
Expand All @@ -203,57 +193,3 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
return boundHandler();
};
}

/**
* Wrap `res.end()` so that it closes the transaction and flushes events before letting the request finish.
*
* Note: This wraps a sync method with an async method. While in general that's not a great idea in terms of keeping
* things in the right order, in this case it's safe, because the native `.end()` actually *is* async, and its run
* actually *is* awaited, just manually so (which reflects the fact that the core of the request/response code in Node
* by far predates the introduction of `async`/`await`). When `.end()` is done, it emits the `prefinish` event, and
* only once that fires does request processing continue. See
* https://github.com/nodejs/node/commit/7c9b607048f13741173d397795bac37707405ba7.
*
* @param origEnd The original `res.end()` method
* @returns The wrapped version
*/
function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod {
return async function newEnd(this: AugmentedNextApiResponse, ...args: unknown[]) {
await finishSentryProcessing(this);

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 {
__DEBUG_BUILD__ && logger.log('Flushing events...');
await flush(2000);
__DEBUG_BUILD__ && logger.log('Done flushing events');
} catch (e) {
__DEBUG_BUILD__ && logger.log('Error while flushing events:\n', e);
}
}
13 changes: 3 additions & 10 deletions packages/nextjs/src/config/wrappers/wrapperUtils.ts
Original file line number Diff line number Diff line change
@@ -1,10 +1,12 @@
import { captureException, getCurrentHub, startTransaction } from '@sentry/core';
import { getActiveTransaction } from '@sentry/tracing';
import { Transaction } from '@sentry/types';
import { baggageHeaderToDynamicSamplingContext, extractTraceparentData, fill } from '@sentry/utils';
import { baggageHeaderToDynamicSamplingContext, extractTraceparentData } from '@sentry/utils';
import * as domain from 'domain';
import { IncomingMessage, ServerResponse } from 'http';

import { autoEndTransactionOnResponseEnd } from './utils/responseEnd';

declare module 'http' {
interface IncomingMessage {
_sentryTransaction?: Transaction;
Expand All @@ -26,15 +28,6 @@ function setTransactionOnRequest(transaction: Transaction, req: IncomingMessage)
req._sentryTransaction = transaction;
}

function autoEndTransactionOnResponseEnd(transaction: Transaction, res: ServerResponse): void {
fill(res, 'end', (originalEnd: ServerResponse['end']) => {
return function (this: unknown, ...endArguments: Parameters<ServerResponse['end']>) {
transaction.finish();
return originalEnd.call(this, ...endArguments);
};
});
}

/**
* Wraps a function that potentially throws. If it does, the error is passed to `captureException` and rethrown.
*
Expand Down
4 changes: 4 additions & 0 deletions packages/nextjs/test/config/withSentry.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -96,6 +96,10 @@ describe('withSentry', () => {
});

it('flushes events before finishing non-erroring response', async () => {
jest
.spyOn(hub.Hub.prototype, 'getClient')
.mockReturnValueOnce({ getOptions: () => ({ tracesSampleRate: 1 } as ClientOptions) } as Client);

await callWrappedHandler(wrappedHandlerNoError, req, res);

expect(flushSpy).toHaveBeenCalled();
Expand Down
2 changes: 1 addition & 1 deletion packages/nextjs/test/config/wrappers.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ describe('data-fetching function wrappers', () => {
describe('starts a transaction and puts request in metadata if tracing enabled', () => {
beforeEach(() => {
req = { headers: {}, url: 'http://dogs.are.great/tricks/kangaroo' } as IncomingMessage;
res = {} as ServerResponse;
res = { end: jest.fn() } as unknown as ServerResponse;

jest.spyOn(SentryTracing, 'hasTracingEnabled').mockReturnValueOnce(true);
});
Expand Down