Skip to content

fix(nextjs): Revert #4139 - remove manipulation of res.finished value #4516

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

Merged
merged 2 commits into from
Feb 8, 2022
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 11 additions & 54 deletions packages/nextjs/src/utils/withSentry.ts
Original file line number Diff line number Diff line change
Expand Up @@ -79,53 +79,12 @@ export const withSentry = (origHandler: NextApiHandler): WrappedNextApiHandler =
try {
const handlerResult = await origHandler(req, res);

// Temporarily mark the response as finished, as a hack to get nextjs to not complain that we're coming back
// from the handler successfully without `res.end()` having completed its work. This is necessary (and we know
// we can do it safely) for a few reasons:
//
// - Normally, `res.end()` is sync and completes before the request handler returns, as part of the handler
// sending data back to the client. As soon as the handler is done, nextjs checks to make sure that the
// response is indeed finished. (`res.end()` signals this by setting `res.finished` to `true`.) If it isn't,
// nextjs complains. ("Warning: API resolved without sending a response for <url>.")
//
// - In order to prevent the lambda running the route handler from shutting down before we can send events to
// Sentry, we monkeypatch `res.end()` so that we can call `flush()`, wait for it to finish, and only then
// allow the response to be marked complete. This turns the normally-sync `res.end()` into an async function,
// which isn't awaited because it's assumed to still be sync. As a result, nextjs runs the aforementioned
// check before the now-async `res.end()` has had a chance to set `res.finished = false`, and therefore thinks
// there's a problem when there's not.
//
// - In order to trick nextjs into not complaining, we can set `res.finished` to `true` before exiting the
// handler. If we do that, though, `res.end()` gets mad because it thinks *it* should be the one to get to
// mark the response complete. We therefore need to flip it back to `false` 1) after nextjs's check but 2)
// before the original `res.end()` is called.
//
// - The second part is easy - we control when the original `res.end()` is called, so we can do the flipping
// right beforehand and `res.end()` will be none the wiser.
//
// - The first part isn't as obvious. How do we know we won't end up with a race condition, such that the
// flipping to `false` might happen before the check, negating the entire purpose of this hack? Fortunately,
// before it's done, our async `res.end()` wrapper has to await a `setImmediate()` callback, guaranteeing its
// run lasts at least until the next event loop. The check, on the other hand, happens synchronously,
// immediately after the request handler (so in the same event loop). So as long as we wait to flip
// `res.finished` back to `false` until after the `setImmediate` callback has run, we know we'll be safely in
// the next event loop when we do so.
//
// And with that, everybody's happy: Nextjs doesn't complain about an unfinished response, `res.end()` doesn’t
// complain about an already-finished response, and we have time to make sure events are flushed to Sentry.
//
// One final note: It might seem like making `res.end()` an awaited async function would run the danger of
// having the lambda close before it's done its thing, meaning we *still* might not get events sent to Sentry.
// Fortunately, even though it's called `res.end()`, and even though it's normally sync, a) it's far from the
// end of the request process, so there's other stuff which needs to happen before the lambda can close in any
// case, and b) that other stuff isn't triggered until `res.end()` emits a `prefinished` event, so even though
// it's not technically awaited, it's still the case that the process can't go on until it's done.
//
// See
// https://github.com/vercel/next.js/blob/e1464ae5a5061ae83ad015018d4afe41f91978b6/packages/next/server/api-utils.ts#L106-L118
// and
// https://github.com/nodejs/node/blob/d8f1823d5fca5e3c00b19530fb15343fdd3c8bf5/lib/_http_outgoing.js#L833-L911.
res.finished = true;
if (process.env.NODE_ENV === 'development') {
// eslint-disable-next-line no-console
console.warn(
'\n[sentry] If Next.js logs a warning "API resolved without sending a response", it\'s a false positive, which we\'re working to rectify.\n',
Copy link
Member

Choose a reason for hiding this comment

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

We can’t use the logger here?

Also why are we emitting a new line at the start?

Copy link
Member Author

Choose a reason for hiding this comment

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

The logger only shows up if the user has debug: true in their config, whereas the warning our message references shows up regardless.

As for the newline, in my testing the message was just kind of getting lost in all the logs, so I stuck some blank lines around it. Do you think it's an issue?

Copy link
Member

Choose a reason for hiding this comment

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

I would prefer to remove the new lines to reduce the noise caused by sentry.

That’s primarily my worry here with the console.warn, that it will cause a lot of noise in the development environment (that can’t be turned off). With debug logging, it’s opt in from the user.

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 can take the newlines out, but bottom line, this creates exactly as much noise as the warning we're causing. It's just that with this logging, it's now

[sentry] There's about to be a warning - it's fine.
Warning - things might be broken.

rather than

Warning - things might be broken.

As a user, I'd rather have that be effectively a two-line warning, including reassurance that I don't need to stress, rather than a one-line warning whose origin and importance I have to wonder about (unless I happen to have turned on debugging in Sentry, which the warning itself gives me no hint that I'd need to do).

The least noise, of course, would be if we weren't causing the warning in the first place, and that's what the original PR accomplished. But given that for the moment we're choosing annoying warning over potential breakage, I really do think it's better to at least let people know why it's there and that it's safe to ignore. Don't you?

Copy link
Member

Choose a reason for hiding this comment

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

Yeah that’s good perspective

Choose a reason for hiding this comment

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

Hello @AbhiPrasad @lobsterkatie, how are you? Is the potential fix being tracked in an issue? Combined with next/auth and swr for fetching the user profile it's triggering a massive amount of logs.

image

Thank you for your hard work 👍

Copy link
Member

Choose a reason for hiding this comment

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

Hey, @Fedeorlandau thanks for reaching out. Could you please open an issue with your setup details? (SDK version, next version, next config), it'll help a ton for us to debug.

);
}

return handlerResult;
} catch (e) {
Expand Down Expand Up @@ -183,8 +142,11 @@ type WrappedResponseEndMethod = AugmentedNextApiResponse['end'];
* 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', as explained in detail in the long comment in the main
* `withSentry()` function.
* 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
Expand All @@ -193,11 +155,6 @@ function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod {
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()`
// method doesn't throw `ERR_STREAM_WRITE_AFTER_END` (which it will if presented with an already-finished response).
this.finished = false;

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