HTTPMiddleware breaks BackgroundTasks in the same connection

[Molkree]

• Initially raised as a discussion in the FastAPI repo.

Consider the following simple example of background tasks through Starlette:
server.py

import logging
from time import sleep

from starlette.applications import Starlette
from starlette.background import BackgroundTasks
from starlette.middleware import Middleware
from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
from starlette.requests import Request
from starlette.responses import JSONResponse, Response
from starlette.routing import Route

logging.basicConfig(
    level=logging.INFO,
    format="[%(asctime)s] [%(levelname)s] %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)


class CustomMiddleware(BaseHTTPMiddleware):
    async def dispatch(
        self, request: Request, call_next: RequestResponseEndpoint
    ) -> Response:
        return await call_next(request)


def create_task(request: Request) -> JSONResponse:
    logging.info("Entered POST method")
    tasks = BackgroundTasks()
    tasks.add_task(background_task)
    message = {"status": "Task created"}
    return JSONResponse(message, background=tasks, status_code=201)


def background_task() -> None:
    logging.info("Started background task")
    sleep(10)
    logging.info("Finished background task")


routes = [Route("/task", endpoint=create_task, methods=["POST"])]
middleware = [Middleware(CustomMiddleware)]
app = Starlette(routes=routes, middleware=middleware)

I start this code with uvicorn server:app --reload.

Then I start the task twice in one connection using this code:
client.py

from httpx import Client

with Client(base_url="http://localhost:8000") as client:
    client.post("/task")
    client.post("/task")

Which results in a sequential execution of background tasks (and read timeout from the client as a consequence):

[2023-03-23 19:32:08] [INFO] Entered POST method
INFO:     127.0.0.1:51448 - "POST /task HTTP/1.1" 201 Created
[2023-03-23 19:32:08] [INFO] Started background task
[2023-03-23 19:32:18] [INFO] Finished background task
[2023-03-23 19:32:18] [INFO] Entered POST method
[2023-03-23 19:32:18] [INFO] Started background task
[2023-03-23 19:32:29] [INFO] Finished background task

If I just send simple curl requests (curl -X 'POST' 'http://127.0.0.1:8000/task') one after the other (so they are different connections), everything works as expected:

[2023-03-23 19:44:35] [INFO] Entered POST method
INFO:     127.0.0.1:55528 - "POST /task HTTP/1.1" 201 Created
[2023-03-23 19:44:35] [INFO] Started background task
[2023-03-23 19:44:37] [INFO] Entered POST method
INFO:     127.0.0.1:55532 - "POST /task HTTP/1.1" 201 Created
[2023-03-23 19:44:37] [INFO] Started background task
[2023-03-23 19:44:45] [INFO] Finished background task
[2023-03-23 19:44:47] [INFO] Finished background task

It looks like this regression was introduced in Starlette 0.23.1, this PR. If I pin Starlette to 0.23.0 everything works fine.

[Kludex]

Thanks for the report @Molkree 👍

[MO-CTO]

I have experienced the same issue. It took me a wile to figure out this was the issue. Only after establishing that the move from Starlette 0.23.0 to 0.23.1 partially broke my FastApi application was I able to find these posts as an explanation of what was going on.

I have been able to resolve it by ditching my @api.middleware('http') middelware and rewriting it as pure ASGI middleware instead, following the documentation here: https://www.starlette.io/middleware/#writing-pure-asgi-middleware.
Hope this helps.

[jsg921019]

@Kludex Is it ok to PR regarding this issue for a review?

[Kludex]

You mean that you want to create a PR? Yeah, go ahead.

[nikita-b]

Is anyone working on this issue? It's quite important for us and I think whether it is necessary to fix it myself or someone is already doing it?

[Kludex]

@nikita-b No one is working on this issue. Go ahead. 🙏

[Kludex]

I need this for the next release.

[Kludex]

It looks like this was the old behavior, then I fix it without knowing in #1609, then I broke it again on #1940.

[Kludex]

I'm not sure if we can fix this without breaking what was previously fixed.

[adriangb]

I’m going to check what the behavior is like under #1700, maybe that’s a viable fix

[adriangb]

I can confirm that #1700 fixes this. I'll re-open it.

[Kludex]

I think we should try to find the cause first, and try to find a solution that just fixes the issue.