Unable to log size of request body using pure ASGI middleware

[markgomez]

I'm trying to get the example from the docs to work but nothing appears to be printing to the console. Here's what I've tried:

Create a basic example:

mkdir foo && cd $_

python3 -m venv .venv

Install dependencies:

. .venv/bin/activate

python3 -m pip install starlette

python3 -m pip install uvicorn

Add source to foo.py (copy-pasted straight from the docs):

touch foo.py

from starlette.applications import Starlette
from starlette.middleware import Middleware
from starlette.responses import JSONResponse
from starlette.routing import Route


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

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

        body_size = 0

        async def receive_logging_request_body_size():
            nonlocal body_size

            message = await receive()
            assert message["type"] == "http.request"

            body_size += len(message.get("body", b""))

            if not message.get("more_body", False):
                print(f"Size of request body was: {body_size} bytes")

            return message

        await self.app(scope, receive_logging_request_body_size, send)


middleware = [
    Middleware(LoggedRequestBodySizeMiddleware),
]


async def homepage(request):
    return JSONResponse({"hello": "world"})


app = Starlette(
    debug=True,
    routes=[
        Route("/", homepage, methods=["GET", "POST"]),
    ],
    middleware=middleware,
)

Run the app:

uvicorn foo:app

In a separate terminal, make a request:

curl --data "foo=bar" http://127.0.0.1:8000

Back in the initial terminal, you should see something like...

INFO:     127.0.0.1:60632 - "POST / HTTP/1.1" 200 OK

...but the final body_size isn't printed anywhere.

If you modify the code to include a print statement outside of receive_logging_request_body_size...

# ...

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

        body_size = 0
        print("Hi!")

        async def receive_logging_request_body_size():
            # ...

...then restart and make a request again, you should see something like this...

INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Hi!
INFO:     127.0.0.1:60666 - "POST / HTTP/1.1" 200 OK

...so at least that parts works, but not sure why the rest doesn't.

[Kludex]

receive_logging_request_body_size is only called if you read the body.

[markgomez]

I see it now. Things work as expected once I add body = await request.form() to the handler. Thanks!