Logging fixes and enhancements (#421)

api/Dockerfile

@@ -13,4 +13,4 @@ RUN python -m pip install -U pip
 # git and put .git (which setuptools_scm needs to determine the version) in the container
 RUN SETUPTOOLS_SCM_PRETEND_VERSION=${VERSION} python -m pip install .
 COPY ./velour_api /src/velour_api
-CMD ["uvicorn", "velour_api.main:app", "--host", "0.0.0.0"]
+CMD ["uvicorn", "velour_api.main:app", "--host", "0.0.0.0", "--log-level", "warning"]

api/velour_api/__init__.py

@@ -9,8 +9,23 @@
     logging_level = 20
 
 
+def status_endpoint_filter(
+    logger,
+    method_name,
+    event_dict,
+    ignore_paths=frozenset(["/health", "/ready"]),
+):
+    if (
+        event_dict.get("path", "") in ignore_paths
+        and event_dict.get("status", 0) == 200
+    ):
+        raise structlog.DropEvent
+    return event_dict
+
+
 structlog.configure(
     processors=[
+        status_endpoint_filter,
         structlog.processors.add_log_level,
         structlog.processors.TimeStamper(fmt="iso"),
         structlog.processors.dict_tracebacks,

api/velour_api/logging.py

@@ -1,29 +1,61 @@
-from typing import Callable
+from typing import Callable, Optional
 
 import structlog
-from fastapi import Request, Response
+from fastapi import BackgroundTasks, HTTPException, Request, Response
 from fastapi.routing import APIRoute
 from starlette.background import BackgroundTask
 
 logger = structlog.get_logger()
 
 
-def log_request(request: Request):
+def log_endpoint(
+    request: Request,
+    status_code: Optional[int],
+):
     logger.info(
         "Velour API Call",
         method=request.method,
         path=request.url.path,
         hostname=request.url.hostname,
+        status=status_code,
     )
 
 
+def add_task(response: Response, task: BackgroundTask) -> Response:
+    if not response.background:
+        response.background = BackgroundTasks([task])
+    elif isinstance(response.background, BackgroundTasks):
+        response.background.add_task(task)
+    else:  # Empirically this doesn't happen but let's handle it anyway
+        if not isinstance(response.background, BackgroundTask):
+            logger.error(
+                "Unexpected response.background",
+                background_type=str(type(response.background)),
+            )
+        old_task = response.background
+        response.background = BackgroundTasks([old_task, task])
+
+    return response
+
+
 class LoggingRoute(APIRoute):
     def get_route_handler(self) -> Callable:
         original_route_handler = super().get_route_handler()
 
         async def custom_route_handler(request: Request) -> Response:
-            response = await original_route_handler(request)
-            BackgroundTask(log_request, request)
-            return response
+            try:
+                response = await original_route_handler(request)
+            except HTTPException as e:
+                log_endpoint(request, e.status_code)
+                raise
+            except Exception:
+                log_endpoint(request, None)
+                logger.exception("Uncaught exception")
+                raise
+            else:
+                task = BackgroundTask(
+                    log_endpoint, request, response.status_code
+                )
+            return add_task(response, task)
 
         return custom_route_handler

docker-compose.yml

@@ -22,7 +22,7 @@ services:
       VELOUR_SECRET_KEY: ${VELOUR_SECRET_KEY}
       VELOUR_USERNAME: ${VELOUR_USERNAME}
       VELOUR_PASSWORD: ${VELOUR_PASSWORD}
-    command: "uvicorn velour_api.main:app --reload --host 0.0.0.0"
+    command: "uvicorn velour_api.main:app --reload --host 0.0.0.0 --log-level warning"
     depends_on:
       - 'db'
       - 'migrations'