Running FastAPI app and getting a Starlette error

[ac000]

Discussed in #1100

^{Originally posted by bunny-therapist January 29, 2024}
I am running a FastAPI app using nginx unit, and using a python script to send multiple sequential (wait for response before sending next) requests to it with the "requests" library. When I reuse the same requests.Session object for all the requests, so that requests.Session.close is not called, then I get intermittent crashes in the application and thus status 500 back.

Traceback (most recent call last):
  File "<path>/venv310/lib/python3.10/site-packages/fastapi/applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/applications.py", line 123, in __call__
    await self.middleware_stack(scope, receive, send)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/errors.py", line 186, in __call__
    raise exc
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/lib/python3.10/contextlib.py", line 153, in __exit__
    self.gen.throw(typ, value, traceback)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
    raise exc
  File "<path>/venv310/lib/python3.10/site-packages/starlette/responses.py", line 257, in wrap
    await func()
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 217, in stream_response
    return await super().stream_response(send)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/responses.py", line 246, in stream_response
    async for chunk in self.body_iterator:
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 181, in body_stream
    raise app_exc
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 151, in coro
    await self.app(scope, receive_or_disconnect, send_no_error)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/lib/python3.10/contextlib.py", line 153, in __exit__
    self.gen.throw(typ, value, traceback)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
    raise exc
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 128, in receive_or_disconnect
    message = await wrap(wrapped_receive)
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 123, in wrap
    result = await func()
  File "<path>/venv310/lib/python3.10/site-packages/starlette/middleware/base.py", line 56, in wrapped_receive
    raise RuntimeError(f"Unexpected message received: {msg['type']}")
RuntimeError: Unexpected message received: http.request

The error is coming from this line: https://github.com/encode/starlette/blob/master/starlette/middleware/base.py#L56
which appears to be starlette waiting for a client disconnect but instead getting the next request. (No idea why starlette wants the request to be closed instead of allowing it to be reused for the next request, but maybe there is something I am not aware of.)

I would (and will) ask about this in the starlette github, but I am posting here because I did not encounter this issue when running my FastAPI app with uvicorn, it only happens with nginx unit, so at a minimum, it appears that something is different here which is causing problems, and this is probably something that should be identified.

I was really happy when I discovered nginx unit; this issue is currently the only thing that is preventing me from adopting it.

[ac000]

Thanks to @bunny-therapist for providing a reproducer, summarised below...

gh1100.py

from fastapi import FastAPI
from fastapi.responses import JSONResponse
from pydantic import BaseModel
from fastapi.responses import  Response

class RequestBody(BaseModel):
    number: int

app = FastAPI()

@app.middleware("http")
async def my_middleware(request, call_next):
    response = await call_next(request)
    return response

@app.post("/predict")
async def post_predict(body: RequestBody):
    return JSONResponse(content={"got": body.number})

@app.get("/data")
async def get_data():
    return Response()

gh1100.json

{
    "listeners": {
        "[::1]:8080": {
            "pass": "applications/fastapi"
        }
    },

    "applications": {
        "fastapi": {
            "type": "python",
            "path": "/home/andrew/src/python",
            "module": "gh1100",
            "callable": "app",
            "protocol": "asgi"
        }
    }
}

gh1100-client.py

#!/usr/bin/python

import requests

N = 2
with requests.Session() as session:
    for _ in range(N):
        r = session.post("http://localhost:8080/predict", json={"number": 1})
        r.raise_for_status()

Running it produces the following in the unit log

2024/01/30 17:01:14 [error] 43868#43868 [unit] #17: Python failed to call 'future.result()'
  + Exception Group Traceback (most recent call last):
  |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 192, in __call__
  |     await response(scope, wrapped_receive, send)
  |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 254, in __call__
  |     async with anyio.create_task_group() as task_group:
  |   File "/home/andrew/.local/lib/python3.12/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/home/andrew/.local/lib/python3.12/site-packages/fastapi/applications.py", line 1054, in __call__
    |     await super().__call__(scope, receive, send)
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/applications.py", line 123, in __call__
    |     await self.middleware_stack(scope, receive, send)
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 186, in __call__
    |     raise exc
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 164, in __call__
    |     await self.app(scope, receive, _send)
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 189, in __call__
    |     with collapse_excgroups():
    |   File "/usr/lib64/python3.12/contextlib.py", line 158, in __exit__
    |     self.gen.throw(value)
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
    |     raise exc
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 261, in __call__
    |     await wrap(partial(self.listen_for_disconnect, receive))
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 257, in wrap
    |     await func()
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 234, in listen_for_disconnect
    |     message = await receive()
    |               ^^^^^^^^^^^^^^^
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 56, in wrapped_receive
    |     raise RuntimeError(f"Unexpected message received: {msg['type']}")
    | RuntimeError: Unexpected message received: http.request
    +------------------------------------

During handling of the above exception, another exception occurred:

  + Exception Group Traceback (most recent call last):
  |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/_utils.py", line 85, in collapse_excgroups
  |     yield
  |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 190, in __call__
  |     async with anyio.create_task_group() as task_group:
  |   File "/home/andrew/.local/lib/python3.12/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Exception Group Traceback (most recent call last):
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 192, in __call__
    |     await response(scope, wrapped_receive, send)
    |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 254, in __call__
    |     async with anyio.create_task_group() as task_group:
    |   File "/home/andrew/.local/lib/python3.12/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
    |     raise BaseExceptionGroup(
    | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
    +-+---------------- 1 ----------------
      | Traceback (most recent call last):
      |   File "/home/andrew/.local/lib/python3.12/site-packages/fastapi/applications.py", line 1054, in __call__
      |     await super().__call__(scope, receive, send)
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/applications.py", line 123, in __call__
      |     await self.middleware_stack(scope, receive, send)
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 186, in __call__
      |     raise exc
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 164, in __call__
      |     await self.app(scope, receive, _send)
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 189, in __call__
      |     with collapse_excgroups():
      |   File "/usr/lib64/python3.12/contextlib.py", line 158, in __exit__
      |     self.gen.throw(value)
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
      |     raise exc
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 261, in __call__
      |     await wrap(partial(self.listen_for_disconnect, receive))
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 257, in wrap
      |     await func()
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 234, in listen_for_disconnect
      |     message = await receive()
      |               ^^^^^^^^^^^^^^^
      |   File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 56, in wrapped_receive
      |     raise RuntimeError(f"Unexpected message received: {msg['type']}")
      | RuntimeError: Unexpected message received: http.request
      +------------------------------------

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/andrew/.local/lib/python3.12/site-packages/fastapi/applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/applications.py", line 123, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 186, in __call__
    raise exc
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/lib64/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/_utils.py", line 91, in collapse_excgroups
    raise exc
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 261, in __call__
    await wrap(partial(self.listen_for_disconnect, receive))
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 257, in wrap
    await func()
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/responses.py", line 234, in listen_for_disconnect
    message = await receive()
              ^^^^^^^^^^^^^^^
  File "/home/andrew/.local/lib/python3.12/site-packages/starlette/middleware/base.py", line 56, in wrapped_receive
    raise RuntimeError(f"Unexpected message received: {msg['type']}")
RuntimeError: Unexpected message received: http.request

This was with Fedora 39 with Python 3.12.1 and fastapi 0.109.0 installed via pip(1)

Looking through git-log(1) these look potentially interesting to look at

commit 567545213d95e608b54ce92bfc33fac4327a9f93
Author: Max Romanov <max.romanov@gmail.com>
Date:   Tue Jul 20 10:37:50 2021 +0300

    Python: fixing ASGI receive() issues.
    
    The receive() call never blocks for a GET request and always returns the sam
e
    empty body message.  The Starlette framework creates a separate task when
    receive() is called in a loop until an 'http.disconnect' message is received
.
    
    The 'http.disconnect' message was previously issued after the response heade
r
    had been sent.  However, the correct behavior is to respond with
    'http.disconnect' after sending the response is complete.
    
    This closes #564 issue on GitHub.

commit dfbdc1c11a201e46d61f4bc61cfbe5741fc4fd70
Author: Max Romanov <max.romanov@gmail.com>
Date:   Tue Jul 20 10:37:53 2021 +0300

    Python: fixing exceptions in Future.set_result for ASGI implementation.
    
    An ASGI application can cancel the Future object returned by the receive()
    call.  In this case, Unit's ASGI implementation should not call set_result()
    because the Future is already handled.  In particular, the Starlette framewo
rk
    was noted to cancel the received Future.
    
    This patch adds a done() check for the Future before attempting a set_result
().
    
    This is related to #564 issue on GitHub.

[bunny-therapist]

Tomorrow, I plan to test out specific starlette commits to pinpoint when exactly the problems appeared.

(You can pip install specific commits from github, see, e.g., https://stackoverflow.com/questions/13685920/install-specific-git-commit-with-pip)

[ac000]

Thanks, that would be helpful...

[bunny-therapist]

I can confirm that the RuntimeError: Unexpected message received error for POST requests started with starlette commit encode/starlette@554b9e2

If I have that commit, I get the error. If i go one commit back in time, the error goes away.

[bunny-therapist]

As for the "invalid state" error for the GET requests, they start with starlette commit encode/starlette@11a3f12

[ac000]

Thanks! I'll take a look...

[akira]

@ac000 bumping on this one, any updates? thanks!

[ac000]

Not yet I'm afraid, I'm sure any updates will be posted here, but I
don't think there is anyone actively working on this currently, so far
it has really just been an information gathering exercise.

[Thijsvandepoll]

Hi I am facing the exact same issue. Is there any progress, or has anyone found some workaround for it?

[bunny-therapist]

I am not following this very closely anymore because I switched from FastAPI to litestar, which works great. Litestar even recommends NGINX Unit in their docs and it is very actively maintained.

With FastAPI, the only way I found around it was to use an older version, fastapi==0.107.0 starlette==0.28.0
(Then again, I have not tried the latest version of FastAPI/starlette because I stopped using it.)

[shadchin]

It helped me - fastapi/fastapi#8187 (reply in thread)