middleware breaks behavior of background task

[jkh911208]

First check

• [x ] I added a very descriptive title to this issue.
• [ x] I used the GitHub search to find a similar issue and didn't find it.
• [ x] I searched the FastAPI documentation, with the integrated search.
• [ x] I already searched in Google "How to X in FastAPI" and didn't find any information.
• [ x] I already read and followed all the tutorial in the docs and didn't find an answer.
• [ x] I already checked if it is not related to FastAPI but to Pydantic.
• [ x] I already checked if it is not related to FastAPI but to Swagger UI.
• [ x] I already checked if it is not related to FastAPI but to ReDoc.
• [ x] After submitting this, I commit to one of:
  • Read open issues with questions until I find 2 issues where I can help someone and add a comment to help there.
  • I already hit the "watch" button in this repository to receive notifications and I commit to help at least 2 people that ask questions in the future.
  • Implement a Pull Request for a confirmed bug.

Example

import asyncio
import logging
import time

from fastapi import FastAPI, Request
from fastapi.responses import JSONResponse
from starlette.background import BackgroundTasks

app = FastAPI()


@app.get("/")
async def read_root():
    response_object = {"Hello": "World"}
    tasks = BackgroundTasks()
    tasks.add_task(bg_task)
    return JSONResponse(response_object, 202, background=tasks)


async def bg_task():
    logging.error("test1")
    await asyncio.sleep(10)
    logging.error("test2")


@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    start_time = time.time()
    response = await call_next(request)
    response.headers["X-Process-Time"] = str(time.time() - start_time)
    response.headers["address"] = request.client.host
    return response

if __name__ == "__main__":
    import uvicorn
    uvicorn.run("main:app", host="0.0.0.0", port=8000,
                log_level="debug", reload=True)

Description

run the above code, make a request to "/"
you will see

which logging is happening before return the object

but if you make only one request at a time this is fine, but if you make multiple request while background task is running

problem #1 the second request start after first background task finishes
problem #2 when background task of second request finishes, it throw error

Environment

• OS: [e.g. Linux / Windows / macOS]: macos and debian
• FastAPI Version [e.g. 0.3.0]: 0.61.1
• Python version: 3.8.5

Additional context

if i remove middleware code it works as expected

all requests are handled and all background tasks are working fine no exception

[ycd]

I believe this is related to Starlette Issue 919: Background tasks don't work with middleware that subclasses BaseHTTPMiddleware

[jkh911208]

thank you @ycd seems like work is still in progress

[Kludex]

@jkh911208 Could you close this issue, please?

[yingyingPengSAP]

For those who are searching for how to call background tasks under FastAPI middleware, here is quick solution:

from starlette.background import BackgroundTask
from somewhere import functionA

@app.middleware("http")
async def middleware(request: Request, call_next):
........(do something)
response.background = BackgroundTask(functionA, arg)
return response

You can add a time.sleep(10) in function A to see the result better.
For tasks running in background, it will return the results of function A
very quickly and will not be affected by time.sleep().

Hope this helps someone!

[santigandolfo]

Hi @jkh911208 @Kludex , why is this issue Closed? Cause I'm trying to use background tasks and a middleware at the same time, and if I send a request to the endpoint through Postman, I receive my response but the request time doesn't finish until the background task does. But if I remove the middleware then it works as expected.

[Kludex]

What is the version of your FastAPI?

Oh sorry, yeah, this is still a thing. encode/starlette#1441

[santigandolfo]

What is the version of your FastAPI?

Oh sorry, yeah, this is still a thing. encode/starlette#1441

I'm on v0.75.2
Do you suggest a workaround until that PR is merged in Starlette and FastAPI bumps it's requirements?

[Kludex]

Yes, don't use BaseHTTPMiddleware.

[santigandolfo]

Yes, don't use BaseHTTPMiddleware.

In that case I couldn't add general before and after request actions, right?

[Kludex]

No, I'm saying to not use that class. You can have middlewares: https://pgjones.dev/blog/how-to-write-asgi-middleware-2021

[Kludex]

This is solved on the latest FastAPI.

[Molkree]

@Kludex, I can't reproduce it only with Starlette.

Here's my attempt:
test_starlette.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)

starlette-requirements.txt

starlette==0.26.1
uvicorn[standard]==0.21.1

Ran with uvicorn test_starlette:app --reload.
Just sent curl requests one after another with curl -X 'POST' 'http://127.0.0.1:8000/task'.

INFO:     Application startup complete.
[2023-03-23 02:20:27] [INFO] Entered POST method
INFO:     127.0.0.1:53582 - "POST /task HTTP/1.1" 201 Created
[2023-03-23 02:20:27] [INFO] Started background task
[2023-03-23 02:20:27] [INFO] Entered POST method
INFO:     127.0.0.1:53583 - "POST /task HTTP/1.1" 201 Created
[2023-03-23 02:20:27] [INFO] Started background task
[2023-03-23 02:20:37] [INFO] Finished background task
[2023-03-23 02:20:37] [INFO] Finished background task

Working as expected.

[Molkree]

@Kludex, alright, I have a clue!

After rewriting the example for Starlette I just used curl, not Swagger UI. The thing is, using curl with FastAPI not causes any issues too!

Just a TLDR: take code from my first message + this requirements.txt:

fastapi
starlette==0.23.1  # or >0.23.0
uvicorn[standard]==0.21.1

Run with uvicorn test_fastapi:app --reload. Open Swagger UI (http://127.0.0.1:8000/docs), and try executing the only POST method twice in succession. The second time will stall for ~10 seconds. Sending the same POST request with other means (curl) works as expected with no stalling.

If you pin Starlette to 0.23.0 instead, executing from Swagger UI won't stall.

Could you confirm you are seeing the same behavior, @Kludex @santigandolfo?

@Kludex, do you think it's a bug with Swagger UI? Or Starlette no longer behaving like it should in this case?

[Kludex]

Ah, the issue happens with the same connection. That's why you see it on Swagger UI - it uses the same connection for both requests. You can also reproduce with:

from httpx import Client

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

I'm not sure how no one noticed this in 4 months. 😞

Would you mind creating an issue on Starlette?

[Molkree]

@Kludex, opened encode/starlette#2093

[Kludex]

Thanks.