sentry-python icon indicating copy to clipboard operation
sentry-python copied to clipboard

RuntimeError: Stream consumed when reading body with startlette (bug since 1.9.10)

Open sevaho opened this issue 2 years ago • 1 comments

How do you use Sentry?

Sentry Saas (sentry.io)

Version

1.9.10

Steps to Reproduce

Server:

import sentry_sdk

from fastapi import FastAPI, Request

sentry_sdk.init()

app = FastAPI()


@app.post("/")
async def index(request: Request):
    r = await request.body()
    return {"Hello": "World"}

Run with uvicorn:

uvicorn app:app --port 5000

As client do:

#! /usr/bin/python
import httpx

import asyncio


async def main():
    image = b"\x89PNG\r\n\x1a\n\x00\x00\x00\rIHDR\x00\x00\x00\x01\x00\x00\x00\x01\x08\x06\x00\x00\x00\x1f\x15\xc4\x89\x00\x00\x00\rIDATx\xdac\xfc\xcf\xf0\xbf\x1e\x00\x06\x83\x02\x7f\x94\xad\xd0\xeb\x00\x00\x00\x00IEND\xaeB`\x82"
    files = {"file": ("test.png", image)}
    async with httpx.AsyncClient() as client:
        r = await client.post(
            "http://localhost:5000/",
            files=files,
        )
        print(r)


asyncio.run(main())

Expected Result

To succeed.

Actual Result

ERROR: Exception in ASGI application Traceback (most recent call last): File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/uvicorn/protocols/http/h11_impl.py", line 404, in run_asgi result = await app( # type: ignore[func-returns-value] File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in call return await self.app(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/fastapi/applications.py", line 270, in call await super().call(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/starlette.py", line 293, in _sentry_patched_asgi_app return await middleware(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/asgi.py", line 138, in _run_asgi3 return await self._run_app(scope, lambda: self.app(scope, receive, send)) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/asgi.py", line 187, in _run_app raise exc from None File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/asgi.py", line 182, in _run_app return await callback() File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/applications.py", line 124, in call await self.middleware_stack(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/starlette.py", line 98, in _create_span_call await old_call(*args, **kwargs) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/middleware/errors.py", line 184, in call raise exc File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/middleware/errors.py", line 162, in call await self.app(scope, receive, _send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/starlette.py", line 191, in _sentry_exceptionmiddleware_call await old_call(self, scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/starlette.py", line 98, in _create_span_call await old_call(*args, **kwargs) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/middleware/exceptions.py", line 79, in call raise exc File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/middleware/exceptions.py", line 68, in call await self.app(scope, receive, sender) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/starlette.py", line 98, in _create_span_call await old_call(*args, **kwargs) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/fastapi/middleware/asyncexitstack.py", line 21, in call raise e File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/fastapi/middleware/asyncexitstack.py", line 18, in call await self.app(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/routing.py", line 706, in call await route.handle(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/routing.py", line 276, in handle await self.app(scope, receive, send) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/routing.py", line 66, in app response = await func(request) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/sentry_sdk/integrations/fastapi.py", line 106, in _sentry_app return await old_app(*args, **kwargs) File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/fastapi/routing.py", line 231, in app raw_response = await run_endpoint_function( File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/fastapi/routing.py", line 160, in run_endpoint_function return await dependant.call(**values) File "/home/sevaho/gitlab/centurion/./app.py", line 14, in read_root r = await request.body() File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/requests.py", line 234, in body async for chunk in self.stream(): File "/home/sevaho/.cache/pypoetry/virtualenvs/centurion-X1KYOsH6-py3.10/lib/python3.10/site-packages/starlette/requests.py", line 215, in stream raise RuntimeError("Stream consumed") RuntimeError: Stream consumed

sevaho avatar Oct 11 '22 19:10 sevaho

Hey @sevaho

Thanks for reporting this. We will have a look when there is time. (Honestly I thought I have fixed this already...)

antonpirker avatar Oct 12 '22 11:10 antonpirker

Thanks @antonpirker !

Looks like there is more to it as well.

@app.post("/")
async def index(request: Request, file: UploadFile = File(...)):
    print(file.filename)
    f = await file.read()
    print(f)
    return ""

Whatever file you pass, the content for await file.read() is always empty due to sentry-sdk absorbing it?

sevaho avatar Oct 17 '22 10:10 sevaho

I am facing the same issue in one of the projects I am involved. I can share just traceback: image

If you need more details, I am happy to help.

mociepka avatar Oct 20 '22 20:10 mociepka

Downgrading to ~1.8 for the time being. Saw this bug on version 1.10.1.

mecampbellsoup avatar Oct 27 '22 12:10 mecampbellsoup

I had about 20k errors caused by this since yesterday and I was off. Downgraded the library once I figured this out. Lost a lot of API calls.

Is there a way to reset quota on sentry because this bug was essentially caused due to sentry library issue?

ranjith19 avatar Oct 28 '22 09:10 ranjith19

Hello! I will have a look at this first thing on Monday!

antonpirker avatar Oct 28 '22 10:10 antonpirker

I was (unplanned so) afk Monday and Tuesday, so I am looking into this now.

antonpirker avatar Nov 02 '22 10:11 antonpirker

This is happening because of some inconsistencies on how Starlette (the foundation of FastAPI) is dealing with request data:

I am now investigating if this should be fixed in Starlette/FastAPI or in Sentry: https://github.com/encode/starlette/discussions/1933

antonpirker avatar Nov 02 '22 14:11 antonpirker

Considering this has been the way starlette has worked for a while now, maybe we could consider the Sentry SDK has "misused" form() and get the fix done here? (To be clear, I do feel starlette has a bit of an inconsistent API for these attributes so it'd be good to clarify with them in https://github.com/encode/starlette/discussions/1933 if it's actually expected and straighten it out, but it's also true that form() has worked like this for a while) Also, many people using Sentry won't be able to get into the latest Starlette version straight away - mainly because a lot of people using FastAPI depend on its pin on Starlette-, so adding the fix here and marking the version 1.9.10 as yanked would make it immediately work for everyone, as well as unblocking further updates of the Sentry SDK library seeing as how people are downgrading to get around the issue.

I am thinking maybe it'd be an option to work around the caching issue by getting it consumed into body() first and introduce a test that breaks when Starlette has their issue fixed? The test could simply be 1) call request.form() 2) expect an exception calling request.body(). When that happens, the workaround can then be removed and maybe Sentry SDK could specify the minimum pin to use Starlette so that it goes hand in hand with the fix. wdyt?

# sentry_sdk/integrations/starlette.py
from starlette.datastructures import FormData
from starlette.formparsers import FormParser, MultiPartParser

async def form(self):
    # type: (StarletteRequestExtractor) -> typing.Optional[typing.Mapping[str, typing.Any]]
    if multipart is None:
        return None

    # Parse the body first to get it cached, as Starlette does not cache form() as it
    # does with body() and json() https://github.com/encode/starlette/discussions/1933
    await self.request.body()
    return await self.request.form()

EDIT: PR by @antonpirker following this approach https://github.com/getsentry/sentry-python/pull/1724 Thanks! 🙏

hasier avatar Nov 03 '22 14:11 hasier

Spent a couple of hours debugging this issue until stumbling upon this ticket. Had zero suspicion that it's Sentry causing it. I was so confused: "how could the body stream be already consumed?". Turns out, the only way to get around it is to downgrade FastAPI or to turn off Sentry.

Here is the piece of code causing this issue:

@app.post(
    "/html",
)
async def post_html_resource(
    request: Request,
):
    data = await request.body()

Where app is a FastAPI class instance and the request is supposed to accept a string as a body. Sentry is initialized before the app instance.

image

vduseev avatar Nov 10 '22 00:11 vduseev

I think this issue can be marked as solved, as it's been fixed in version 1.11.0 (it's working for me at least). Thanks for your work @antonpirker! 🙇

hasier avatar Nov 23 '22 14:11 hasier

This appears to still be an issue for us in v1.11.1. Not sure if we are doing something wrong. Will investigate further.

MrSaints avatar Dec 06 '22 02:12 MrSaints

Yeah I am seeing this as well in v1.11.1

br-follow avatar Dec 15 '22 07:12 br-follow

having the issue as well in v1.13.0 . Can we please consider re-opening it?

Sebadst avatar Mar 09 '23 14:03 Sebadst

Is this fixed in v1.19.x?

ranjith19 avatar Apr 13 '23 11:04 ranjith19

:(

caner-cetin avatar Apr 19 '23 07:04 caner-cetin

Seeing this in 1.25.1 and not really understanding the circumstances that cause it. Anyone got a useful link?

smzelek avatar Aug 10 '23 21:08 smzelek

To everyone commenting that this is still broken, please ensure you are not using any other middlewares, as it is not just Sentry that would cause this issue. Any middleware which reads from the request's form() method is going to break if that result is not cached. Realistically this is a bug / design flaw with Starlette/FastAPI that should be fixed on that end.

@caner-cetin if you are not even using this library, then this is definitely not the place you should be commenting. Try commenting on an existing issue in the Starlette or FastAPI repos, or making your own in those repos.

acnebs avatar Aug 11 '23 04:08 acnebs

I wanted to come back here to say that the issue I experienced was actually due to exception handling middleware I wrote that should've checked whether the Request had been disconnected.

FastAPI will catch when the Request stream is disconnected, which eventually gets raised as a starlette.exceptions.HTTPException, with an upstream error of RuntimeError("Stream consumed"). All CustomRouteHandler style Middlewares will be in the stack trace, even though they have nothing to do with the error. (SentrySDK is implemented in this style as well, which is why it will appear in the stack trace and lead one to think its related to the error.)

The solution to this is to check for instances of starlette.exceptions.HTTPException and check if the request was disconnected.

Leaving this example here for posterity, as I imagine lots of other people will get confused seeing sentry in the stacktrace if they do something similar, as this is a common approach to writing a generic FastAPI middleware.

class CustomRouteHandler(APIRoute):
    def get_route_handler(self) -> Callable:
        original_route_handler = super().get_route_handler()

        async def handle_route(request: Request) -> Response:
            try:
                response = await original_route_handler(request)

            except Exception as exc:
                if not await request.is_disconnected():
                    # ... handle non-disconnect errors

                response = ApiErrorResponse(error=ErrorDetails(code=..., message='...'))

            return response

smzelek avatar Aug 11 '23 19:08 smzelek

@acnebs Yep, I am sorry for my needless outrage, problem was in MinIO Python SDK, it was reading the stream and not rewinding after read, leaving me with errors when trying to read the same file after uploading to MinIO.

Sorry again! <3

caner-cetin avatar Aug 12 '23 08:08 caner-cetin