Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Bug: LoggingMiddleware breaks static file serving #3516

Open
1 of 4 tasks
wallseat opened this issue May 22, 2024 · 0 comments
Open
1 of 4 tasks

Bug: LoggingMiddleware breaks static file serving #3516

wallseat opened this issue May 22, 2024 · 0 comments
Labels
Bug 🐛 This is something that is not working as expected

Comments

@wallseat
Copy link

wallseat commented May 22, 2024 •
edited
Loading

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/[email protected]/swagger-ui-bundle.js
   - https://cdn.jsdelivr.net/npm/[email protected]/swagger-ui.css
   - https://cdn.jsdelivr.net/npm/[email protected]/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

  • Linux
  • Mac
  • Windows
  • Other (Please specify in the description above)

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
@wallseat wallseat added the Bug 🐛 This is something that is not working as expected label May 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug 🐛 This is something that is not working as expected
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@wallseat