Skip to content

Bug: Logging middelware bug when a middleware raises an exception. #4855

Description

@abdulhaq-e

Description

I'm using the main branch in production in several projects and I've been noticing an exception appearing in my logs that trace back to the logging middleware. This is probably a regression because I was on older commit and things were working fine.

Perhaps I'm writing middelwares incorrectly and such a design shouldn't be supported but here is what's happening: if an inner middleware (e.g. a custom auth middleware) raises an exception then the logging middleware will raise KeyError at line

connection_state.log_context.pop(HTTP_RESPONSE_BODY),
. This happens because in the normal flow of the request/response, the logging context dictionary doesn't get populated with a field called 'http.response.body' (a.k.a HTTP_RESPONSE_BODY).

The following test has been generated with the help of an LLM:

def test_logging_middleware_no_keyerror_when_auth_middleware_raises_before_send(caplog: "LogCaptureFixture") -> None:
    """Regression test: LoggingMiddleware must not raise KeyError when an HTTPException
    is raised from an inner middleware before any ASGI send call (e.g. an auth middleware
    that rejects the request outright without sending a response body).

    Before the fix, the except-HTTPException branch in LoggingMiddleware.handle() set
    HTTP_RESPONSE_START in log_context but never set HTTP_RESPONSE_BODY, so
    extract_response_data() would KeyError on the .pop() and the whole request would
    surface as 500 instead of the intended 401.
    """

    class AlwaysRejectAuthMiddleware(AbstractAuthenticationMiddleware):
        async def authenticate_request(self, connection: ASGIConnection) -> AuthenticationResult:
            raise NotAuthorizedException("Token expired")

    @get("/protected")
    def protected_handler() -> dict:
        return {"secret": "data"}

    with (
        create_test_client(
            route_handlers=[protected_handler],
            middleware=[
                LoggingMiddleware(
                    "litestar.test",
                    response_log_fields=["status_code"],
                    request_log_fields=["path"],
                ),
                DefineMiddleware(AlwaysRejectAuthMiddleware),
            ],
        ) as client,
        caplog.at_level(INFO),
    ):
        response = client.get("/protected")
        # Before the fix this was 500 because KeyError propagated through the middleware stack
        assert response.status_code == 401
        assert any("status_code=401" in msg for msg in caplog.messages)

The LLM also suggested a fix by setting a default value for the field in after lines

scope_state.log_context[HTTP_RESPONSE_START] = {"status": exc.status_code}
and
scope_state.log_context[HTTP_RESPONSE_START] = {"status": HTTP_500_INTERNAL_SERVER_ERROR}
, happy to create a PR

URL to code causing the issue

No response

MCVE

Steps to reproduce

  1. Go to '...'
  2. Click on '....'
  3. Scroll down to '....'
  4. See error

Screenshots

No response

Logs


Litestar Version

main branch

Platform

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    Bug 🐛This is something that is not working as expected

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions