Skip to content

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

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

Code after yield in the async dependecy executed before response has been sent to the client #5068

Closed
9 tasks done
FNSdev opened this issue Jun 23, 2022 · 9 comments
Closed
9 tasks done
Labels
question Question or problem question-migrate

Comments

@FNSdev
Copy link

FNSdev commented Jun 23, 2022

First Check

  • I added a very descriptive title to this issue.
  • I used the GitHub search to find a similar issue and didn't find it.
  • I searched the FastAPI documentation, with the integrated search.
  • I already searched in Google "How to X in FastAPI" and didn't find any information.
  • I already read and followed all the tutorial in the docs and didn't find an answer.
  • I already checked if it is not related to FastAPI but to Pydantic.
  • I already checked if it is not related to FastAPI but to Swagger UI.
  • I already checked if it is not related to FastAPI but to ReDoc.

Commit to Help

  • I commit to help with one of those options 👆

Example Code

import asyncio
from typing import AsyncGenerator

import structlog
import uvicorn
from fastapi import FastAPI, Depends
from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
from starlette.requests import Request
from starlette.responses import Response

logger = structlog.getLogger(__name__)


app = FastAPI()


class BarMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
        logger.info("BAR: Before call_next()")
        response = await call_next(request)
        logger.info("BAR: After call_next()")
        logger.info(f"BAR: Status code {response.status_code}")

        logger.info("BAR: Before sleep()")
        await asyncio.sleep(2)
        logger.info("BAR: After sleep()")

        return response


class ZxcMiddleware(BaseHTTPMiddleware):
    async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
        logger.info("ZXC: Before call_next()")
        response = await call_next(request)
        logger.info("ZXC: After call_next()")
        logger.info(f"ZXC: Status code {response.status_code}")

        logger.info("ZXC: Before sleep()")
        await asyncio.sleep(2)
        logger.info("ZXC: After sleep()")

        return response


async def get_foo() -> AsyncGenerator[str, None]:
    logger.info("BEFORE YIELD FOO")
    yield "foo"
    logger.info("AFTER YIELD FOO")


async def get_qwerty(foo: str = Depends(get_foo)) -> AsyncGenerator[str, None]:
    logger.info("BEFORE YIELD QWERTY")
    yield "qwerty"
    logger.info("AFTER YIELD QWERTY")


@app.get("/")
async def root(qwerty: str = Depends(get_qwerty)):
    return {"message": qwerty}


app.add_middleware(BarMiddleware)
app.add_middleware(ZxcMiddleware)


if __name__ == "__main__":
    uvicorn.run(
        "test:app",
        host="0.0.0.0",
        port=8080,
        reload=True,
    )

Description

Hi.

From the documentation:

The code following the yield statement is executed after the response has been delivered:

But this is not the case:

2022-06-23 09:21:29,932 uvicorn.error INFO: Finished server process [30197]
2022-06-23 09:21:30,309 uvicorn.error INFO: Started server process [30216]
2022-06-23 09:21:30,309 uvicorn.error INFO: Waiting for application startup.
2022-06-23 09:21:30,309 uvicorn.error INFO: Application startup complete.
2022-06-23 09:22.12 [info     ] ZXC: Before call_next()
2022-06-23 09:22.12 [info     ] BAR: Before call_next()
2022-06-23 09:22.12 [info     ] BEFORE YIELD FOO
2022-06-23 09:22.12 [info     ] BEFORE YIELD QWERTY
2022-06-23 09:22.12 [info     ] BAR: After call_next()
2022-06-23 09:22.12 [info     ] BAR: Status code 200
2022-06-23 09:22.12 [info     ] BAR: Before sleep()
2022-06-23 09:22.14 [info     ] BAR: After sleep()
2022-06-23 09:22.14 [info     ] ZXC: After call_next()
2022-06-23 09:22.14 [info     ] ZXC: Status code 200
2022-06-23 09:22.14 [info     ] ZXC: Before sleep()
2022-06-23 09:22.14 [info     ] AFTER YIELD QWERTY
2022-06-23 09:22.14 [info     ] AFTER YIELD FOO
2022-06-23 09:22.16 [info     ] ZXC: After sleep()
2022-06-23 09:22:16,494 uvicorn.access INFO: 127.0.0.1:55382 - "GET / HTTP/1.1" 200

Response has not been sent to the client yet, but we're already in the "after yield" code. I can not reproduce it with a single middleware though.

Using native ASGI middlewares (instead of inheriting from BaseHTTPMiddleware) does not solve the issue.

It's a problem for us, because we can not rely on the fact that transaction has been commited already (in the middleware), when we're in the "after yield" code.

Either docs are misleading, or something works incorrectly.

Operating System

Linux

Operating System Details

No response

FastAPI Version

0.78.0

Python Version

3.8.10

Additional Context

No response

@FNSdev FNSdev added the question Question or problem label Jun 23, 2022
@JarroVGIT
Copy link
Contributor

JarroVGIT commented Jun 23, 2022

Could you please post your code in which you tried native ASGI middleware? You say you tried it, but didn't solve the issue, can we assume that it yielded the same behaviour as with BaseHTTPMiddleware?

I would highly recommend to use native ASGI middleware anyway, as BaseHTTPMiddleware will might be deprecated (see this open issue on the Starlette project: Issue). So having the starting point where you see this behaviour with native ASGI middleware would help me reproduce this (and hopefully, help you fix it ;))

@JarroVGIT
Copy link
Contributor

This is actually much stranger behaviour than I would expect to be honest. I wrote the ASGI middleware myself, and then the code after yield is even immediately called after the response has been sent (and before it has been handled by the middleware). I thought "maybe it is the asyncio.sleep, which is throwing back control to the event loop" but that made no difference at all.

Code:

import asyncio
from typing import AsyncGenerator

import uvicorn
import logging
from fastapi import FastAPI, Depends
from starlette.requests import Request
from starlette.responses import Response

logger = logging.getLogger()

app = FastAPI(debug=True)

class BarMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            return await self.app(scope, receive, send)
        logger.warning("BAR: Before call self.app()")   
        status_code = 1
        async def send_wrapper(message):
            if message["type"] == "http.response.start":
                nonlocal status_code
                status_code = message["status"]
            await send(message)
        r = await self.app(scope, receive, send_wrapper)
        logger.warning("BAR: After call self.app()")
        logger.warning(f"BAR: Status code {status_code}")
        logger.warning("BAR: Before sleep()")
        #await asyncio.sleep(2)
        logger.warning("BAR: After sleep()")

class ZxcMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            return await self.app(scope, receive, send)
        logger.warning("ZXC: Before call self.app()")
        status_code = 1
        async def send_wrapper(message):
            if message["type"] == "http.response.start":
                nonlocal status_code
                status_code = message["status"]
            await send(message)
        r = await self.app(scope, receive, send_wrapper)
        logger.warning("ZXC: After call self.app()")
        logger.warning(f"ZXC: Status code {status_code}")
        logger.warning("ZXC: Before sleep()")
        #await asyncio.sleep(2)
        logger.warning("ZXC: After sleep()")

async def get_foo() -> AsyncGenerator[str, None]:
    logger.warning("BEFORE YIELD FOO")
    yield "foo"
    logger.warning("AFTER YIELD FOO")

async def get_qwerty(foo: str = Depends(get_foo)) -> AsyncGenerator[str, None]:
    logger.warning("BEFORE YIELD QWERTY")
    yield "qwerty"
    logger.warning("AFTER YIELD QWERTY")

app.add_middleware(BarMiddleware)
app.add_middleware(ZxcMiddleware)

@app.get("/")
async def root(qwerty: str = Depends(get_qwerty)):
    return {"message": qwerty}

if __name__ == "__main__":
    uvicorn.run(app, host="0.0.0.0", port=8000,  )

My logging:

ZXC: Before call self.app()
BAR: Before call self.app()
BEFORE YIELD FOO
BEFORE YIELD QWERTY
INFO:     127.0.0.1:62160 - "GET / HTTP/1.1" 200 OK
AFTER YIELD QWERTY
AFTER YIELD FOO
BAR: After call self.app()
BAR: Status code 200
BAR: Before sleep()
BAR: After sleep()
ZXC: After call self.app()
ZXC: Status code 200
ZXC: Before sleep()
ZXC: After sleep()

This doesn't make sense to me at all to be honest. I am really curious to your ASGI middleware, and the behaviour in that.

@FNSdev
Copy link
Author

FNSdev commented Jun 24, 2022

That's what I have tried.

import asyncio
from typing import AsyncGenerator

import structlog
import uvicorn
from fastapi import FastAPI, Depends
from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
from starlette.requests import Request
from starlette.responses import Response

logger = structlog.getLogger(__name__)


app = FastAPI()


@app.middleware("http")
async def bar_middleware(request, call_next):
    logger.info("BAR: Before call_next()")
    response = await call_next(request)
    logger.info("BAR: After call_next()")

    logger.info("BAR: Before sleep()")
    await asyncio.sleep(2)
    logger.info("BAR: After sleep()")

    return response


@app.middleware("http")
async def zxc_middleware(request, call_next):
    logger.info("ZXC: Before call_next()")
    response = await call_next(request)
    logger.info("ZXC: After call_next()")
    logger.info(f"ZXC: Status code {response.status_code}")

    logger.info("ZXC: Before sleep()")
    await asyncio.sleep(2)
    logger.info("ZXC: After sleep()")

    return response


async def get_foo() -> AsyncGenerator[str, None]:
    logger.info("BEFORE YIELD FOO")
    yield "foo"
    logger.info("AFTER YIELD FOO")


async def get_qwerty(foo: str = Depends(get_foo)) -> AsyncGenerator[str, None]:
    logger.info("BEFORE YIELD QWERTY")
    yield "qwerty"
    logger.info("AFTER YIELD QWERTY")


@app.get("/")
async def root(qwerty: str = Depends(get_qwerty)):
    return {"message": qwerty}


if __name__ == "__main__":
    uvicorn.run(
        "test:app",
        host="0.0.0.0",
        port=8080,
        reload=True,
    )

The result:
image

@JarroVGIT
Copy link
Contributor

That is using httpbasemiddleware as well? (The decorator ‘ @app.middleware("http")’ is just syntax sugarcoating for inheriting from BaseHTTPMiddleware.

@FNSdev
Copy link
Author

FNSdev commented Jun 24, 2022

My bad, sorry, you're right. It works as I would expect with a real native middleware. Thank you.

import asyncio
from typing import AsyncGenerator

import uvicorn
import logging
from fastapi import FastAPI, Depends

logger = logging.getLogger()

app = FastAPI(debug=True)


class BarMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            return await self.app(scope, receive, send)
        logger.warning("BAR: Before call self.app()")

        async def send_wrapper(message):
            if message["type"] == "http.response.start":
                logger.warning("BAR: Before sleep()")
                await asyncio.sleep(2)
                logger.warning("BAR: After sleep()")

            await send(message)

        await self.app(scope, receive, send_wrapper)

        logger.warning("BAR: After call self.app()")


class ZxcMiddleware:
    def __init__(self, app):
        self.app = app

    async def __call__(self, scope, receive, send):
        if scope["type"] != "http":
            return await self.app(scope, receive, send)
        logger.warning("ZXC: Before call self.app()")

        async def send_wrapper(message):
            if message["type"] == "http.response.start":
                logger.warning("ZXC: Before sleep()")
                await asyncio.sleep(2)
                logger.warning("ZXC: After sleep()")

            await send(message)

        await self.app(scope, receive, send_wrapper)

        logger.warning("ZXC: After call self.app()")


async def get_foo() -> AsyncGenerator[str, None]:
    logger.warning("BEFORE YIELD FOO")
    yield "foo"
    logger.warning("AFTER YIELD FOO")


async def get_qwerty(foo: str = Depends(get_foo)) -> AsyncGenerator[str, None]:
    logger.warning("BEFORE YIELD QWERTY")
    yield "qwerty"
    logger.warning("AFTER YIELD QWERTY")


app.add_middleware(BarMiddleware)
app.add_middleware(ZxcMiddleware)


@app.get("/")
async def root(qwerty: str = Depends(get_qwerty)):
    return {"message": qwerty}


if __name__ == "__main__":
    uvicorn.run(
        "test:app",
        host="0.0.0.0",
        port=8080,
        reload=True,
    )

ZXC: Before call self.app()
BAR: Before call self.app()
BEFORE YIELD FOO
BEFORE YIELD QWERTY
BAR: Before sleep()
BAR: After sleep()
ZXC: Before sleep()
ZXC: After sleep()
INFO:     127.0.0.1:32962 - "GET / HTTP/1.1" 200 OK
AFTER YIELD QWERTY
AFTER YIELD FOO
BAR: After call self.app()
ZXC: After call self.app()

But I still believe that either docs need to be updated, or there must be a disclaimer to avoid using BaseHttpMiddleware.

@JarroVGIT
Copy link
Contributor

Interesting, I thought that was the wrong order. The docs say:

If you have dependencies with `yield`, the exit code will run *after* the middleware.

So, I figured the

AFTER YIELD QWERTY
AFTER YIELD FOO

would appear as latest in the logging stack. Maybe I am interpreting the documentation incorrectly, because the code after yield is being executed after the middleware has had its turn with the incoming request, but I expected the code dealing with outgoing response would adhere to this too (e.g. first you would see BAR: After call self.app(), then ZXC: After call self.app() and then AFTER YIELD QWERTY/FOO).

By the way, that is why my response was that it was strange behaviour, funny that you expected that very behaviour your self 😋

@FNSdev
Copy link
Author

FNSdev commented Jun 24, 2022

INFO:     127.0.0.1:32962 - "GET / HTTP/1.1" 200 OK
AFTER YIELD QWERTY
AFTER YIELD FOO

So from my understanding, it looks correct, response was sent already, we got back to our dependencies.

The difference here is that we're actually logging in the middleware AFTER the response has been sent, which was not possible using BaseHttpMiddleware. But I don't see a problem here. Docs do not specify when we should get to that point, before or after deps.

In our case we're only interested in commiting / rolling back the transaction. It can be done in the place of "After sleep" log message (in the send_wrapper), which is executed before response has been sent. So it's exactly what we want.

@Kludex
Copy link
Sponsor Collaborator

Kludex commented Jun 25, 2022

BaseHTTPMiddleware will be deprecated (see this open issue on the Starlette project: Issue). So having the starting point where you see this behaviour with native ASGI middleware would help me reproduce this (and hopefully, help you fix it ;))

That's not for sure yet... There has been a lot of discussion about BaseHTTPMiddleware. Also, the limitations of BaseHTTPMiddleware are usually not a problem for most of the users.

That being said... They are still limitations, and if you are going to have them, for the time being, pure ASGI middlewares are recommended.

@JarroVGIT
Copy link
Contributor

BaseHTTPMiddleware will be deprecated (see this open issue on the Starlette project: Issue). So having the starting point where you see this behaviour with native ASGI middleware would help me reproduce this (and hopefully, help you fix it ;))

That's not for sure yet... There has been a lot of discussion about BaseHTTPMiddleware. Also, the limitations of BaseHTTPMiddleware are usually not a problem for most of the users.

That being said... They are still limitations, and if you are going to have them, for the time being, pure ASGI middlewares are recommended.

Fair point, I corrected my comment above 😇

Repository owner locked and limited conversation to collaborators Feb 28, 2023
@tiangolo tiangolo converted this issue into discussion #8529 Feb 28, 2023

This issue was moved to a discussion.

You can continue the conversation there. Go to discussion →

Labels
question Question or problem question-migrate
Projects
None yet
Development

No branches or pull requests

4 participants