fix(logging): reading empty body when extracting request data (#207)

* 🐛 fix(logging): catch error when reading an empty request body

* ✅ test(logging): add unit test

* 🐛 fix(logging): ensure body is None when catching RuntimeError

* ♻️ refactor: fix mypy

.tool-versions

@@ -0,0 +1 @@
+python 3.11.0

src/starlite_saqlalchemy/log/controller.py

@@ -31,6 +31,7 @@
 
 HTTP_RESPONSE_START: Literal["http.response.start"] = "http.response.start"
 HTTP_RESPONSE_BODY: Literal["http.response.body"] = "http.response.body"
+REQUEST_BODY_FIELD: Literal["body"] = "body"
 
 
 def drop_health_logs(_: WrappedLogger, __: str, event_dict: EventDict) -> EventDict:
@@ -190,7 +191,14 @@ async def extract_request_data(self, request: Request) -> dict[str, Any]:
             if value is missing:  # pragma: no cover
                 continue
             if isawaitable(value):
-                value = await value
+                # Prevent Starlite from raising a RuntimeError
+                # when trying to read an empty request body.
+                try:
+                    value = await value
+                except RuntimeError:
+                    if key != REQUEST_BODY_FIELD:
+                        raise
+                    value = None
             data[key] = value
         return data
 

tests/unit/test_log.py

@@ -9,7 +9,8 @@
 
 import pytest
 import structlog
-from starlite import get, post
+from starlite import Request, get, post
+from starlite.connection.base import empty_receive
 from starlite.constants import SCOPE_STATE_RESPONSE_COMPRESSED
 from starlite.status_codes import (
     HTTP_200_OK,
@@ -378,7 +379,9 @@ async def test_after_process_logs_at_error(job: Job, cap_logger: CapturingLogger
 
 
 async def test_exception_in_before_send_handler(
-    client: TestClient[Starlite], cap_logger: CapturingLogger, monkeypatch: MonkeyPatch
+    client: TestClient[Starlite],
+    cap_logger: CapturingLogger,
+    monkeypatch: MonkeyPatch,
 ) -> None:
     """Test we handle errors originating from trying to log a request in the
     before-send handler."""
@@ -400,6 +403,33 @@ def test_handler() -> str:
     assert call.kwargs["exception"]
 
 
+async def test_exception_in_before_send_handler_read_empty_body(
+    client: TestClient[Starlite],
+    cap_logger: CapturingLogger,
+    before_send_handler: log.controller.BeforeSendHandler,
+    http_scope: HTTPScope,
+) -> None:
+    """Test we handle errors originating from trying to log a request in the
+    before-send handler."""
+
+    @post(media_type="text/plain")
+    def test_handler() -> str:
+        return "Hello"
+
+    request: Request = Request(http_scope, receive=empty_receive)
+    await before_send_handler.extract_request_data(request)
+
+    client.app.register(test_handler)
+    resp = client.post("/")
+    assert resp.text == "Hello"
+    assert len(cap_logger.calls) == 1
+    call = cap_logger.calls[0]
+    assert call.method_name == "info"
+    assert call.kwargs["event"] == "HTTP"
+    assert call.kwargs["request"]["body"] is None
+    assert "exception" not in call.kwargs
+
+
 @pytest.mark.xfail(reason="starlite is returning 500 for invalid payloads as of v1.48.1")
 async def test_log_request_with_invalid_json_payload(client: TestClient[Starlite]) -> None:
     """Test logs emitted with invalid client payload.