ref(nextjs): Use flush code from withSentry in all backend wrappers
#5814
Conversation
size-limit report 📦
|
| // 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(); | ||
| }); | ||
| }); |
There was a problem hiding this comment.
m: Do we actually know whether this is necessary? In which scenarios would spans be finished after res.end() has been called?
There was a problem hiding this comment.
To be fair, in nextjs I'm not sure it is. It's logic originally from
sentry-javascript/packages/node/src/handlers.ts
Lines 86 to 94 in a5bfa80
withSentry.
UPDATE: I just checked the blame, and it turns out that for express, the setImmediate() was introduced in #3022 to fix #3001. I don't see any analogs to that problem for nextjs, so yeah, I think we can get rid of it. Will do.
There was a problem hiding this comment.
On second thought, what if the user has manually added a span which finishes on res.end()? Or what if an integration does? As long as we drop spans which haven't finished, part of me feels like it can't hurt to leave this in. WDYT?
There was a problem hiding this comment.
For some reason I am just weirded out by this. It shouldn't be necessary. I am a little bit scared that this is the reason serverside tracing wasn't working in the first place. I would like to test this properly before we include it.
As for
what if the user has manually added a span which finishes on res.end()? Or what if an integration does?
I think these are pretty niche cases. (The integration one not quite but it's something we generally own ourselves)
And generally I am in favor of just having less code.
There was a problem hiding this comment.
I am a little bit scared that this is the reason serverside tracing wasn't working in the first place.
I still don't have good theories on that (among other things, why it works reliably when using the debugger, but not always when not), but in that case the transaction wasn't even starting - instead the code was falling off somewhere in instrumentServer. So I can't see how this would have had any effect there.
It shouldn't be necessary.
I think these are pretty niche cases. (The integration one not quite but it's something we generally own ourselves)
Agreed that right now there's nothing that I can see in the nextjs SDK which makes it necessary. And I just looked at all of the node integrations and I think none of them needs it*. But I don't necessarily want to count on the fact that every future person who writes a node integration, even if they're on our team, will remember to either a) stay away from ending a span on response end or b) remember to put the setImmediate back in if they do.
*The only exception is the express integration, which someone could conceivably use if they're using a custom server. Then again, we've made no effort to support that use case, so we might not care that much.
For some reason I am just weirded out by this.
Can you say more about why? It's been running like this successfully in withSentry for the last 18 months, so I'm not sure I understand the bad feeling you're getting.
There was a problem hiding this comment.
Ok let's leave it. I admit my sketched-out-ness is a bit irrational and just a gut-feeling. Still kinda sceptical but ok with it.
| await finishTransaction(res); | ||
| await flushQueue(); |
There was a problem hiding this comment.
m: Aren't we calling these two functions twice now for the API routes? Once here and once implicitly above with autoEndTransactionOnResponseEnd? If so, we could delete finishTransaction by moving its logic into autoEndTransactionOnResponseEnd which would also remove the need for __sentryTransaction.
There was a problem hiding this comment.
The problem is that res.end() doesn't always get called if there's an error. See #4027.
There was a problem hiding this comment.
Ah ok got it. If that is the case, I find the __sentryTransaction solution still a little bit overcomplicated. I think we should just lift up the declaration of the transaction variable and pass in the transaction directly instead of writing it on res.
Something like (this would also ofc involve changing the signature of finishTransaction):
@@ -1,5 +1,6 @@
import { captureException, getCurrentHub, startTransaction } from '@sentry/node';
import { extractTraceparentData, hasTracingEnabled } from '@sentry/tracing';
+import { Transaction } from '@sentry/types';
import {
addExceptionMechanism,
baggageHeaderToDynamicSamplingContext,
@@ -76,6 +77,7 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
// getting that before it will finish the response.
const boundHandler = local.bind(async () => {
const currentScope = getCurrentHub().getScope();
+ let transaction: Transaction | undefined;
if (currentScope) {
currentScope.setSDKProcessingMetadata({ request: req });
@@ -110,7 +112,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',
@@ -176,7 +178,7 @@ export function withSentry(origHandler: NextApiHandler, parameterizedRoute?: str
// 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 finishTransaction(res);
+ await finishTransaction(transaction);
await flushQueue();
// We rethrow here so that nextjs can do with the error whatever it would normally do. (Sometimes "whatever itWdyt?
There was a problem hiding this comment.
I don't feel strongly either way, but I'll admit I don't get how attaching the transaction to the response is any more complicated than attaching it to the request (which we do elsewhere and which was, IIRC, your idea...)
There was a problem hiding this comment.
I don't get how attaching the transaction to the response is any more complicated than attaching it to the request (which we do elsewhere and which was, IIRC, your idea...)
Attaching the transaction to the request was done out of necessity since datafetchers need to share a transaction to spawn child spans, but they have no other reliable way of sharing data except via the req/res objects.
I would never do that simply because it's an option. Attaching stuff to req/res, just to extract it in the step directly after (while we would have it available as a simple variable) is just an indirection I'd like to avoid.
There was a problem hiding this comment.
But we can do this in a separate PR.
| }; | ||
|
|
||
| // Prevent double-wrapping | ||
| if (!(res.end as WrappedResponseEndMethod).__sentry_original__) { |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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).
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
What I want to check (and can't, because first I have to figure out why suddenly my computer's lost its mind and lost track of yarn and node) is what actually ends up in
Don't the nextjs docs say they always will be, though?
I can fix this in this PR. No point in doing another one. Like I said, even though I disagree with you about attaching it to the response being especially complex, I don't have a strong feeling one way or the other on which way we do it, so I'm fine to switch it. |
Yeah, you're right. I don't know wtf is going on anymore. I just redeployed the same exact thing and it's not failing anymore. I guess we're good after all on this front. Nonetheless, I potentially found a way to make
Yeah idk. Maybe this is a kneejerk reaction. |
lobsterkatie
force-pushed
the
kmclb-nextjs-enable-flush-in-data-fetchers-wrapper
branch
from
94059ca
to
45eba7a
Compare
lobsterkatie
deleted the
kmclb-nextjs-enable-flush-in-data-fetchers-wrapper
branch
BTW, I fixed my computer and did check this, and indeed, it's the |
Yeah I don't know what happened there - I probably fudged something in my Vercel test setup. Sorry about that! |
When deployed to Vercel, nextjs apps have their route handlers converted to AWS lambdas, which use the vercel node runtime. In this runtime, AWS's
callbackWaitsForEmptyEventLoopcontext option is set tofalse. As a result, it's possible for a route-handling lambda to be shut down before events have finished sending to Sentry. To ensure that this doesn't happen, inwithSentrywe wrapres.end, so that it flushes all of our events before the response marks itself as finished.This extracts that logic into its own module, so that it can also be used in the other
withSentryXwrappers (withSentryServerSidePropsand the like).