Blocked code while using middleware and dependency injections to log requests in FastAPI(Python)

Question

Please, help me to coupe the problem of blocked code. I am using FastAPI.

I've done with a middleware to log incoming requests and server responses for them.

@app.middleware("http")
async def log_request(request: Request, call_next):

    # Code to log incoming request
    response = await call_next(request)
    # Code to log response 
    return response

I have an endpoint without dependency injection:

@app.post("/without-dependency-injection", tags=["Test"])
async def check_response_without_using_dependency():

    # ... Any code
    return {"token":"token123"}

Here is a console with a log written by middleware:

[17.08.2021 13:08:25.08S]: {"event_type": "Incoming request", "id": "3fb33dc0-cb86-49e9-9a0f-c48596e58061"}
[17.08.2021 13:08:25.08S]: {"event_type": "Outgoing response", "id": "3fb33dc0-cb86-49e9-9a0f-c48596e58061"}
INFO:     127.0.0.1:50285 - "POST /without-dependency-injection HTTP/1.1" 200 OK

Everything works well! Middleware catches the request, writes log with a request details, execute request, write log with the server response and return response to a client.

Behavior will change when i add dependency.

This is an endpoint with dependency injection:

@app.post("/generate-token/", tags=["Test"])
async def create_access_token(form_data: OAuth2PasswordRequestForm = Depends()):
    
    # ...
    # Code to generate token

    return {"token":f"{token}"}

And here is a console log:

[17.08.2021 13:13:08.13S]: {"event_type": "Incoming request", "id": "3b6398de-5b20-40ad-820e-24733425e6c7"}

As you see, there is no "Outgoing response" event. Middleware caught the request, logged incoming request data and sent request to an execution. And a code was blocked... until server get a new request. Only after that client will get a response from a server.

If I remove a middleware or dependency injection, everything works well.

Who knows why the code is blocked until server will get a new request from a client? How to fix this behavior?

Answer 1

The Basic Info, Root-Cause & the Rant

Hey, I have spent a fair amount of time stuck in this hanging issue (for critical apps in my org which have multiple custom MDW). This is basically because @app.middleware("http") based middlewares, are in back-end created by inheriting from Starlette's BaseHTTPMiddleware. So this problem also exists for MDWs written by inheriting from BaseHTTPMiddleware explicitly. The reasons for this are quite complex and I have been not been able to fully understand them, however this is what I have understood so far:

1. from here (GitHub Starlette Issue) and here (Github FastAPI Issue): I learnt that this method uses StreamingResponse which has some issues
2. from here (GitHub Starlette Issue): I learnt that one of the reasons for hanging is: awaiting request.json() is allowed only once in request life-cycle in API, and BaseHTTPMiddleware also creates a Request object on its own (which causes hanging issue, since that is another request)

The last link also mentions that what also causes the hanging issue, is that, because of StreamingResponse; the reading of response somehow gets exhausted in the first read, and when it comes to the second read, it keeps on waiting for it indefinitely which causes the hanging. (first and second read here means: in ASGI APPs, messages are sent to-and-from client & APP with various types like http.response.start, http.response.body etc)

The Solution (partial, logs response, but I will update when I learn for requests too)

So, don't use anything to do with BaseHTTPMiddleware. To combat this I wrote all my custom middlewares using ASGI Specification given here

You can make your custom middleware like this:

from starlette.types import ASGIApp, Receive, Send, Message

class LogResponseMDW:

    def __init__(self, app: ASGIApp) -> None:
        self.app = app
    
    async def __call__(self, scope: Scope, receive: Receive, send: Send):

        async def send_wrapper(message: Message):
            # This will capture response coming from APP Layer
            # You will want to check for message["type"] first
            # response body will be in message where the type is
            # "http.response.body"
            print(f"message: {message}") # log here, after checking the message type
            await send(message)
        
        await self.app(scope, receive, send_wrapper)


# you can add this to your app this way:
app.add_middleware(LogResponseMDW)