litestar-org / litestar

Production-ready, Light, Flexible and Extensible ASGI API framework | Effortlessly Build Performant APIs
https://litestar.dev/
MIT License
5.57k stars 379 forks source link

Bug: LoggingMiddleware breaks static file serving #3516

Open wallseat opened 5 months ago

wallseat commented 5 months ago

Description

If you try to add logging middleware without excluded /static route, then you will get the following error

Traceback (most recent call last):
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/streaming.py", line 134, in send_body
    await self._listen_for_disconnect(cancel_scope=task_group.cancel_scope, receive=receive)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/streaming.py", line 100, in _listen_for_disconnect
    await self._listen_for_disconnect(cancel_scope=cancel_scope, receive=receive)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/streaming.py", line 94, in _listen_for_disconnect
    message = await receive()
              ^^^^^^^^^^^^^^^
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 535, in receive
    await self.message_event.wait()
  File "/usr/lib/python3.11/asyncio/locks.py", line 213, in wait
    await fut
asyncio.exceptions.CancelledError: Cancelled by cancel scope 7f9a8eadd150

During handling of the above exception, another exception occurred:

  + Exception Group Traceback (most recent call last):
  |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 219, in __call__
  |     await self.app(scope, receive, send)
  |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/routes/http.py", line 86, in handle
  |     await response(scope, receive, send)
  |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 200, in __call__
  |     await self.send_body(send=send, receive=receive)
  |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/file.py", line 187, in send_body
  |     await super().send_body(send=send, receive=receive)
  |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/streaming.py", line 132, in send_body
  |     async with create_task_group() as task_group:
  |   File "/workdir/.venv/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/streaming.py", line 117, in _stream
    |     await send(stream_event)
    |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/logging.py", line 226, in send_wrapper
    |     self.log_response(scope=scope)
    |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/logging.py", line 136, in log_response
    |     extracted_data = self.extract_response_data(scope=scope)
    |                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/logging.py", line 194, in extract_response_data
    |     connection_state.log_context.pop(HTTP_RESPONSE_START),
    |     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    | KeyError: 'http.response.start'
    +------------------------------------

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 219, in __call__
    await self.app(scope, receive, send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/base.py", line 129, in wrapped_call
    await original__call__(self, scope, receive, send)  # pyright: ignore
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/logging.py", line 112, in __call__
    await self.app(scope, receive, send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 233, in __call__
    await self.handle_request_exception(
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 263, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/logging.py", line 227, in send_wrapper
    await send(message)
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 496, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 219, in __call__
    await self.app(scope, receive, send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/_asgi/asgi_router.py", line 89, in __call__
    await asgi_app(scope, receive, send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 233, in __call__
    await self.handle_request_exception(
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 263, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 496, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 407, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
    return await self.app(scope, receive, send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/app.py", line 590, in __call__
    await self.asgi_handler(scope, receive, self._wrap_send(send=send, scope=scope))  # type: ignore[arg-type]
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 233, in __call__
    await self.handle_request_exception(
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/middleware/exceptions/middleware.py", line 263, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/workdir/.venv/lib/python3.11/site-packages/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/workdir/.venv/lib/python3.11/site-packages/uvicorn/protocols/http/h11_impl.py", line 496, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

URL to code causing the issue

No response

MCVE

from typing import Final

from litestar import Litestar
from litestar.logging import StructLoggingConfig
from litestar.middleware.logging import LoggingMiddlewareConfig
from litestar.openapi import OpenAPIConfig
from litestar.openapi.plugins import SwaggerRenderPlugin
from litestar.static_files import create_static_files_router

logging_config: Final = StructLoggingConfig()

logging_middleware: Final = LoggingMiddlewareConfig(
    # exclude=["/static"],
    request_log_fields=["path", "method", "content_type", "query", "path_params"],
    response_log_fields=["status_code"],
).middleware

openapi_config: Final = OpenAPIConfig(
    title="Insourcing API",
    version="0.1.0",
    render_plugins=[
        SwaggerRenderPlugin(
            js_url="/static/swagger-ui-bundle.js",
            standalone_preset_js_url="/static/swagger-ui-standalone-preset.js",
            css_url="/static/swagger-ui.css",
        ),
    ],
    path="/docs",
)

app = Litestar(
    route_handlers=[
        create_static_files_router(
            path="/static",
            directories=["./static/"],
            include_in_schema=False,
        ),
    ],
    openapi_config=openapi_config,
    logging_config=logging_config,
    middleware=[logging_middleware],
)

Steps to reproduce

1. Copy+paste code example
2. Create `static` folder near script
3. Download and put this 3 files
   - https://cdn.jsdelivr.net/npm/swagger-ui-dist@5.1.3/swagger-ui-bundle.js
   - https://cdn.jsdelivr.net/npm/swagger-ui-dist@5.1.3/swagger-ui.css
   - https://cdn.jsdelivr.net/npm/swagger-ui-dist@5.1.3/swagger-ui-standalone-preset.js
4. Run with uvicorn - `uvicorn test:app --host 0.0.0.0 --port 8000`
5. Open localhost:8000/docs
6. Got an error
7. Uncomment line 13
8. Run again
9. Get no error

Litestar Version

2.8.2

Platform

wsl - 2.1.5.0 ubuntu - 23.04


[!NOTE]
While we are open for sponsoring on GitHub Sponsors and OpenCollective, we also utilize Polar.sh to engage in pledge-based sponsorship.

Check out all issues funded or available for funding on our Polar.sh dashboard

  • If you would like to see an issue prioritized, make a pledge towards it!
  • We receive the pledge once the issue is completed & verified
  • This, along with engagement in the community, helps us know which features are a priority to our users.

Fund with Polar

kshivakumar commented 1 month ago

I tested with the latest version of Litestar on Mac, but I didn't encounter the error mentioned above.