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

Sentry.sentryHandle() raises TypeError: Body is unusable: Body has already been read when node >= 20 (20.x, 22.x) #14583

Open
3 tasks done
chenqianhe opened this issue Dec 5, 2024 · 23 comments
Labels
Migrated Package: sveltekit Issues related to the Sentry SvelteKit SDK Waiting for: Community

Comments

@chenqianhe
Copy link

Is there an existing issue for this?

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/sveltekit

SDK Version

8.42.0

Framework Version

"@sveltejs/kit": "^2.6.2", "svelte": "^4.1.2", "@sveltejs/adapter-vercel": "^5.5.0"

Link to Sentry event

https://learnie-ai.sentry.io/issues/6106002320/events/32c06c33715a481caeabbb2569eb7853/?project=4505632768262144

Reproduction Example/SDK Setup

On hooks.server.ts:

Sentry.init({
    dsn: "xxx",
    tracesSampleRate: 1.0,
    integrations: [Sentry.consoleIntegration(), Sentry.captureConsoleIntegration({ levels: ["error"] })],
    enabled: import.meta.env.MODE === "production",
});

export const handle = sequence(Sentry.sentryHandle(), mySelfHandle);

Steps to Reproduce

  1. Use node 20.x or node 22.x (btw, no bugs on Node 18.x)
  2. Enable Sentry
  3. Send multiple requests to an interface at the same time

Expected Result

All requests are received and returned normally

Actual Result

A small number (one or two) of them return results normally, but the rest all have errors:

TypeError: Body is unusable: Body has already been read
    at consumeBody (node:internal/deps/undici/undici:5463:15)
    at _Request.json (node:internal/deps/undici/undici:5416:18)
    at POST (file:///var/task/vercel/path0/.svelte-kit/output/server/entries/endpoints/api/v1/quiz/freeform/_server.ts.js:20:32)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async render_endpoint (file:///var/task/vercel/path0/.svelte-kit/output/server/index.js:184:20)
    at async resolve2 (file:///var/task/vercel/path0/.svelte-kit/output/server/index.js:2721:22)
    at async sessionCookieInvalidationHandle (file:///var/task/vercel/path0/.svelte-kit/output/server/chunks/hooks.server.js:68:20)
    at async /var/task/vercel/path0/node_modules/@sentry/sveltekit/build/cjs/server/handle.js:140:21
    at async instrumentHandle (/var/task/vercel/path0/node_modules/@sentry/sveltekit/build/cjs/server/handle.js:128:27)
    at async respond (file:///var/task/vercel/path0/.svelte-kit/output/server/index.js:2615:22)
@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Dec 5, 2024
@github-actions github-actions bot added the Package: sveltekit Issues related to the Sentry SvelteKit SDK label Dec 5, 2024
@chenqianhe
Copy link
Author

chenqianhe commented Dec 5, 2024

  1. I'm sure it's not from mySelfHandle, because I tried it and everything worked fine:
export const handle = sequence(mySelfHandle, mySelfHandle);
  1. I'm sure it's a Sentry related error because everything works fine after I removed it:
export const handle = sequence(mySelfHandle);
  1. I don't think it's an error caused by undici, because I checked the source code and found that the clone function in fetch provided by undici is indeed a so-called deep copy. (Node implemented fetch on undici after Node 20.x, different between Node 18.x, But I didn't find much difference in their behavior)

https://github.com/nodejs/undici/blob/9e6d34d6dcf47aed9da997550cba6f158983b20c/lib/web/fetch/request.js#L760

https://github.com/nodejs/undici/blob/9e6d34d6dcf47aed9da997550cba6f158983b20c/lib/web/fetch/body.js#L286

  1. I also checked Sentry.sentryHandle() source code, but I really don't have any clues

@s1gr1d
Copy link
Member

s1gr1d commented Dec 5, 2024

Hello, can you provide a small runnable reproduction example? This can be for example a GitHub repository with a small SvelteKit project that includes e.g. a button for the request and the Sentry setup. Thank you! :)

@chenqianhe
Copy link
Author

Hello, can you provide a small runnable reproduction example? This can be for example a GitHub repository with a small SvelteKit project that includes e.g. a button for the request and the Sentry setup. Thank you! :)

https://github.com/chenqianhe/node-20-sentry-demo

https://node-20-sentry-demo.vercel.app/

I have to say, at the moment I can't reproduce this bug in either this minimal example or our real project.

@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Dec 5, 2024
@getsantry getsantry bot moved this from Waiting for: Product Owner to Waiting for: Community in GitHub Issues with 👀 3 Dec 5, 2024
@Lms24
Copy link
Member

Lms24 commented Dec 5, 2024

Hey @chenqianhe just chiming in here with some extra context. I can't think of a specific reason why you'd get this error. Do we know if this happens on the request or the response?

If request: The only thing we do is that we clone the original request to extract request data which later on would get attached to error events (for errors during this request cycle). I used .clone() specifically to avoid double-reading the request but maybe this is not enough?

If response: The only way we'd potentially change a respnse body is by injecting some Html into the rendered page. However, we use SvelteKit's official transformPageChunk hook for this so if that is the problem, it's potentially a SvelteKit bug 🤔

Let us know once you can reproduce this and if you by chance find out more!

@chenqianhe
Copy link
Author

Hey @chenqianhe just chiming in here with some extra context. I can't think of a specific reason why you'd get this error. Do we know if this happens on the request or the response?

If request: The only thing we do is that we clone the original request to extract request data which later on would get attached to error events (for errors during this request cycle). I used .clone() specifically to avoid double-reading the request but maybe this is not enough?

If response: The only way we'd potentially change a respnse body is by injecting some Html into the rendered page. However, we use SvelteKit's official transformPageChunk hook for this so if that is the problem, it's potentially a SvelteKit bug 🤔

Let us know once you can reproduce this and if you by chance find out more!

According to the Sentry error, this happens on the request. I find it very strange too - Sentry shouldn't cause this kind of issue. I've also checked the corresponding source code, which shows that it operates after cloning, and there's no body reading involved.

I'm now suspecting whether it might be errors caused by other reasons that eventually surfaced at this point, leading to a misdiagnosis/false identification.

@getsantry getsantry bot moved this from Waiting for: Community to Waiting for: Product Owner in GitHub Issues with 👀 3 Dec 5, 2024
@Lms24
Copy link
Member

Lms24 commented Dec 5, 2024

From MDN:

clone() throws a TypeError if the request body has already been used. In fact, the main reason clone() exists is to allow multiple uses of body objects (when they are one-use only.)

So I do think we're using clone() correctly but maybe something is accessing the request before the sentryHandle handler? Can you confirm that sentryHandle is the first handler that's called in your handle sequence?

@Shuuru
Copy link

Shuuru commented Dec 12, 2024

Hey. I'm having the same issue.

TypeError: Body is unusable: Body has already been read
     at consumeBody (node:internal/deps/undici/undici:5656:15)
     at _Request.json (node:internal/deps/undici/undici:5609:18)
     at POST (/home/azureuser/dash/src/routes/api/audit/get/+server.js:9:65)
     at Module.render_endpoint (/home/azureuser/dash/node_modules/@sveltejs/kit/src/runtime/server/endpoint.js:43:24)
     at resolve (/home/azureuser/dash/node_modules/@sveltejs/kit/src/runtime/server/respond.js:451:23)
     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
     at async eval (/home/azureuser/dash/src/hooks.server.js:387:19)
     at async /home/azureuser/dash/node_modules/@sentry/sveltekit/build/cjs/server/handle.js:131:21
     at async instrumentHandle (/home/azureuser/dash/node_modules/@sentry/sveltekit/build/cjs/server/handle.js:117:27)
     at async Module.respond (/home/azureuser/dash/node_modules/@sveltejs/kit/src/runtime/server/respond.js:327:20)

I'm using:
"@sentry/sveltekit": "^8.42.0", "@sveltejs/kit": "^2.10.1", "svelte": "^4.2.18", "@sveltejs/adapter-node": "^5.2.9"

I also have:

export const handle = sequence(Sentry.sentryHandle(), secondaryHandle);

I can POST 5 times and it doesn't happen, but on the 6th it will, and then the 7th it's fine. Not to that exact cadence, but the point is it's sporadic, with no change to the request body.

One thing to note is that while it is happening in my dev VM (5.10.0-33-cloud-amd64) on both vite dev and vite build, it is not happening when the exact code is deployed to our staging/production env on Azure App Services. Both are running Node 20 LTS.

@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Dec 12, 2024
@Lms24
Copy link
Member

Lms24 commented Dec 13, 2024

Thanks! I reached out to Vercel internally if they have an idea what might be going on.

@Lms24
Copy link
Member

Lms24 commented Dec 16, 2024

Quick update: If anyone can provide a reliable minimal reproduction, we're happy to take a look (also the svelte maintainers). For now, this unfortunately is too unspecific to debug. Thanks!

@getsantry getsantry bot moved this to Waiting for: Community in GitHub Issues with 👀 3 Jan 22, 2025
@nilsroehrig
Copy link

@Lms24 We've been facing this issue in production for a while now and weren't able to reproduce it, only to observe it. I applied your suggestion to the code to see wether it's still observable. I'll provide an update in one or two weeks, because it's rather rare but happens continuously.

Maybe it helps with diagnosing the root cause, but for us, it only ever happened on two specific POST requests. One form action and one API endpoint. We don't have other API endpoints, but a bunch of other form actions. None of them ever showed the issue.

@getsantry getsantry bot moved this from Waiting for: Community to Waiting for: Product Owner in GitHub Issues with 👀 3 Jan 29, 2025
@Lms24
Copy link
Member

Lms24 commented Jan 29, 2025

Thanks a lot @nilsroehrig - appreciate the help! 🙏

Does the form action where this happens do anything with the request that your other actions don't do (or vice versa)?

@nilsroehrig
Copy link

The form action only consumes request.formData() and that's it. But by looking through it I noticed something else: both the preview endpoint function as well as the form action function are created by a factory function for testability and dependency injection. This is seemingly not the case anywhere else. Could be an issue on our side in the end. But since the request is just an argument for the inner function, I wonder how this could affect each other. I think I need to investigate this a bit more.

@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Jan 29, 2025
@getsantry getsantry bot moved this to Waiting for: Community in GitHub Issues with 👀 3 Jan 29, 2025
@nilsroehrig
Copy link

After about two weeks of deploying the patch, I can confirm that we are not observing the Body is unusable error anymore! As for the root cause, I'm still not sure where it comes from. I may report back, once I have an answer to that, but for now, the patch works.

@getsantry getsantry bot moved this from Waiting for: Community to Waiting for: Product Owner in GitHub Issues with 👀 3 Feb 11, 2025
@Lms24
Copy link
Member

Lms24 commented Feb 11, 2025

Thanks for getting back to us! I'll open a PR then with a fix. If this causes other issues, it's easy to revert, so let's give it a broader try.

@jycouet
Copy link

jycouet commented Feb 14, 2025

It's probably linked with a version of SvelteKit as well.
I wanted to look into this today, and found the issue and the fix. Perfect timing for me. Thank you 😉

I bumped to 9.1.0, now let's see 🚀

@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Feb 14, 2025
@getsantry getsantry bot moved this to Waiting for: Community in GitHub Issues with 👀 3 Feb 14, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Migrated Package: sveltekit Issues related to the Sentry SvelteKit SDK Waiting for: Community
Projects
Status: Waiting for: Community
Development

No branches or pull requests