Provide more information in error log by logging request body for val…

src/error_handling/error_handling.py

@@ -7,6 +7,7 @@
 from fastapi import HTTPException, status
 from pydantic import BaseModel
 from starlette.responses import JSONResponse
+from fastapi.exceptions import RequestValidationError
 
 
 def as_http_exception(exception: Exception) -> HTTPException:
@@ -27,17 +28,35 @@ class ErrorSchema(BaseModel):
     reference: str
 
 
+async def _get_body_content(request) -> str:
+    body = getattr(request, "_body", None)
+    if body is None:
+        try:
+            body = await request.body()
+        except RuntimeError:
+            # The request body stream may already be consumed by the request handler.
+            # In that case FastAPI/Starlette raises RuntimeError when attempting to read it again.
+            return "<Data Stream with unknown content>"
+
+    if not body:
+        return ""
+
+    try:
+        return json.dumps(json.loads(body))
+    except (json.JSONDecodeError, TypeError):
+        if isinstance(body, bytes):
+            return body.decode("utf-8", errors="replace")
+        return str(body)
+
+
 async def http_exception_handler(request, exc):
     reference = uuid.uuid4().hex
     error = ErrorSchema(detail=exc.detail, reference=reference)
     content = error.dict()
 
-    body_content = "<Data Stream with unknown content>"
-    if not request._stream_consumed:
-        body = await request.body()
-        body_content = json.dumps(json.loads(body)) if body else ""
+    body_content = await _get_body_content(request)
 
-    log_message = str(
+    log_message = json.dumps(
         {
             "reference": reference,
             "exception": f"{str(exc)!r}",
@@ -51,3 +70,26 @@ async def http_exception_handler(request, exc):
         log_level = logging.WARNING
     logging.log(log_level, log_message)
     return JSONResponse(content, status_code=exc.status_code)
+
+
+async def validation_exception_handler(request, exc: RequestValidationError):
+    reference = uuid.uuid4().hex
+
+    body_content = await _get_body_content(request)
+
+    log_message = {
+        "reference": reference,
+        "exception": str(exc),
+        "method": request.scope["method"],
+        "path": request.scope["path"],
+        "body": body_content,
+    }
+
+    logging.debug(str(log_message))
+
+    content = {
+        "detail": exc.errors(),
+        "reference": reference,
+    }
+
+    return JSONResponse(content, status_code=422)

src/main.py

@@ -33,7 +33,10 @@
 from setup_logger import setup_logger
 from taxonomies.synchronize_taxonomy import synchronize_taxonomy_from_file
 from triggers import disable_review_process, enable_review_process
-from error_handling import http_exception_handler
+from error_handling.error_handling import (
+    http_exception_handler,
+    validation_exception_handler,
+)
 from routers import (
     resource_routers,
     parent_routers,
@@ -53,6 +56,7 @@
     add_deprecation_and_sunset_middleware,
     Version,
 )
+from fastapi.exceptions import RequestValidationError
 
 
 def add_routes(app: FastAPI, version: Version, url_prefix=""):
@@ -174,6 +178,7 @@ def build_app(*, url_prefix: str = "", version: str = "dev"):
     for app, version in [(main_app, Version.LATEST)] + versioned_apps:
         add_routes(app, version=version)
         app.add_exception_handler(HTTPException, http_exception_handler)
+        app.add_exception_handler(RequestValidationError, validation_exception_handler)
         add_deprecation_and_sunset_middleware(app)
         add_version_to_openapi(app)
 

src/tests/test_error_response.py

@@ -1,11 +1,35 @@
 import logging
 
+from tests.testutils.users import logged_in_user
+
 
 def test_reference_json_and_log_match(client, caplog):
     url_raises_because_dataset_does_not_exist = "/datasets/42"
     with caplog.at_level(logging.DEBUG):
         response = client.get(url_raises_because_dataset_does_not_exist).json()
 
-    assert "reference" in response, response
+    assert "reference" in response, response  # noqa: S101
     reference_in_log = response["reference"] in caplog.text
-    assert reference_in_log, "The reference provided to the user should be in the log."
+    assert reference_in_log, "The reference provided to the user should be in the log."  # noqa: S101
+
+
+def test_duplicate_upload_logs_request_body(client, body_asset: dict, auto_publish: None, caplog):
+    body = dict(body_asset)
+    body["type"] = "storage"
+
+    with logged_in_user():
+        response = client.post(
+            "/computational_assets", json=body, headers={"Authorization": "Fake token"}
+        )
+    assert response.status_code == 200, response.json()  # noqa: S101
+
+    with logged_in_user(), caplog.at_level(logging.DEBUG):
+        response = client.post(
+            "/computational_assets",
+            json={"invalid": "payload"},
+            headers={"Authorization": "Fake token"},
+        )
+
+    assert response.status_code in (400, 422), response.json()  # noqa: S101
+    assert "<Data Stream with unknown content>" not in caplog.text  # noqa: S101
+    assert "invalid" in caplog.text  # noqa: S101