Merge pull request #256 from bento-platform/feat/logging/django-access-middleware

feat(logging): create Django request middleware

Author: davidlougheed

bento_lib/logging/structured/__init__.py

@@ -1,4 +1,6 @@
-from .configure import configure_structlog
+from .configure import configure_structlog, configure_structlog_uvicorn
 
-# re-export configure_structlog() function
-__all__ = ["configure_structlog"]
+# re-export functions:
+#  - configure_structlog()
+#  - configure_structlog_uvicorn()
+__all__ = ["configure_structlog", "configure_structlog_uvicorn"]

bento_lib/logging/structured/common.py

@@ -0,0 +1,53 @@
+import time
+from pydantic import BaseModel
+from structlog.stdlib import BoundLogger
+
+__all__ = [
+    "LogHTTPInfo",
+    "LogNetworkInfo",
+    "LogNetworkClientInfo",
+    "log_access",
+]
+
+
+class LogHTTPInfo(BaseModel):
+    url: str
+    status_code: int
+    method: str
+    version: str | None  # If None, not known (in the case of the Django development server)
+
+
+class LogNetworkClientInfo(BaseModel):
+    host: str | None
+    port: int | None
+
+
+class LogNetworkInfo(BaseModel):
+    client: LogNetworkClientInfo
+
+
+def _client_str(client: LogNetworkClientInfo) -> str:
+    return f"{client.host or ''}{':' + str(client.port) if client.port else ''}"
+
+
+def _http_str(http: LogHTTPInfo) -> str:
+    http_str = f"HTTP/{http.version}" if http.version else "HTTP"
+    return f'"{http.method} {http.url} {http_str}" {http.status_code}'
+
+
+async def log_access(logger: BoundLogger, start_time_ns: int, http_info: LogHTTPInfo, network_info: LogNetworkInfo):
+    # When the response has finished or errored out, write the access log message:
+
+    duration = time.perf_counter_ns() - start_time_ns
+
+    await logger.ainfo(
+        # The message format mirrors the original uvicorn access message, which we aim to replace here with
+        # something more structured.
+        f"{_client_str(network_info.client) or '<unknown>'} - {_http_str(http_info)}",
+        # HTTP information, extracted from the request and response objects:
+        http=http_info.model_dump(mode="json", exclude_none=True),
+        # Network information, extracted from the request object:
+        network=network_info.model_dump(mode="json"),
+        # Duration in nanoseconds, computed in-middleware:
+        duration=duration,
+    )

bento_lib/logging/structured/django.py

@@ -0,0 +1,70 @@
+import time
+
+from asgiref.sync import iscoroutinefunction, markcoroutinefunction
+from django.http import HttpRequest, HttpResponse
+from rest_framework import status
+from structlog.stdlib import BoundLogger
+from typing import Awaitable, Callable
+
+from .common import LogHTTPInfo, LogNetworkInfo, LogNetworkClientInfo, log_access
+
+__all__ = [
+    "BentoDjangoAccessLoggerMiddleware",
+]
+
+
+class BentoDjangoAccessLoggerMiddleware:
+    """
+    Quasi-factory class to build an access-logging Django middleware class via the make_django_middleware() method.
+    Similar to the authorization middleware for Django/FastAPI, we set this up as a "middleware factory" so that we can
+    inject logger instances.
+    """
+
+    def __init__(self, access_logger: BoundLogger, service_logger: BoundLogger):
+        self._access_logger = access_logger
+        self._service_logger = service_logger
+
+    def make_django_middleware(self):
+        class InnerMiddleware:
+            async_capable = True
+            sync_capable = False
+
+            # noinspection PyMethodParameters
+            def __init__(inner_self, get_response: Callable[[HttpRequest], Awaitable[HttpResponse]]):
+                inner_self.get_response = get_response
+                if iscoroutinefunction(inner_self.get_response):  # pragma: no cover
+                    markcoroutinefunction(inner_self)
+
+            # noinspection PyMethodParameters
+            async def __call__(inner_self, request: HttpRequest):
+                start_time = time.perf_counter_ns()
+
+                response: HttpResponse = HttpResponse(status=status.HTTP_500_INTERNAL_SERVER_ERROR)
+                try:
+                    response = await inner_self.get_response(request)
+                except Exception as e:  # pragma: no cover
+                    await self._service_logger.aexception("uncaught exception", exc_info=e)
+                finally:
+                    # When the response has finished or errored out, write the access log message:
+                    # noinspection PyTypeChecker
+                    await log_access(
+                        self._access_logger,
+                        start_time,
+                        http_info=LogHTTPInfo(
+                            url=request.get_full_path(),
+                            status_code=response.status_code,
+                            method=request.method,
+                            version=None,
+                        ),
+                        network_info=LogNetworkInfo(
+                            client=LogNetworkClientInfo(
+                                # Match what uvicorn shows:
+                                host=request.META.get("REMOTE_HOST"),
+                                port=request.META.get("REMOTE_PORT"),
+                            )
+                        ),
+                    )
+
+                    return response
+
+        return InnerMiddleware

bento_lib/logging/structured/fastapi.py

@@ -1,8 +1,10 @@
 import structlog
 import time
-from fastapi import Request, Response
+from fastapi import Request, Response, status
 from uvicorn.protocols.utils import get_path_with_query_string
 
+from .common import LogHTTPInfo, LogNetworkInfo, LogNetworkClientInfo, log_access
+
 __all__ = [
     "build_structlog_fastapi_middleware",
 ]
@@ -24,40 +26,27 @@ async def access_log_middleware(request: Request, call_next) -> Response:
         start_time = time.perf_counter_ns()
 
         # To return if an exception occurs while calling the next in the middleware chain
-        response: Response = Response(status_code=500)
+        response: Response = Response(status_code=status.HTTP_500_INTERNAL_SERVER_ERROR)
 
         try:
             response = await call_next(request)
         except Exception as e:  # pragma: no cover
             await service_logger.aexception("uncaught exception", exc_info=e)
         finally:
             # When the response has finished or errored out, write the access log message:
-
-            duration = time.perf_counter_ns() - start_time
-
-            status_code = response.status_code
             # noinspection PyTypeChecker
-            url = get_path_with_query_string(request.scope)
-            client_host = request.client.host
-            client_port = request.client.port
-            http_method = request.method
-            http_version = request.scope["http_version"]
-
-            await access_logger.ainfo(
-                # The message format mirrors the original uvicorn access message, which we aim to replace here with
-                # something more structured.
-                f'{client_host}:{client_port} - "{http_method} {url} HTTP/{http_version}" {status_code}',
-                # HTTP information, extracted from the request and response objects:
-                http={
-                    "url": url,
-                    "status_code": status_code,
-                    "method": http_method,
-                    "version": http_version,
-                },
-                # Network information, extracted from the request object:
-                network={"client": {"host": client_host, "port": client_port}},
-                # Duration in nanoseconds, computed in-middleware:
-                duration=duration,
+            await log_access(
+                access_logger,
+                start_time,
+                http_info=LogHTTPInfo(
+                    url=get_path_with_query_string(request.scope),
+                    status_code=response.status_code,
+                    method=request.method,
+                    version=request.scope["http_version"],
+                ),
+                network_info=LogNetworkInfo(
+                    client=LogNetworkClientInfo(host=request.client.host, port=request.client.port)
+                ),
             )
 
             return response

tests/django_test_project/django_test_project/logger.py

@@ -1,5 +1,12 @@
-import logging
+import structlog.stdlib
+from bento_lib.logging.structured.django import BentoDjangoAccessLoggerMiddleware
 
-__all__ = ["logger"]
+__all__ = ["logger", "access_middleware"]
 
-logger = logging.getLogger(__name__)
+logger = structlog.stdlib.get_logger("test.logger")
+
+access = BentoDjangoAccessLoggerMiddleware(
+    access_logger=structlog.stdlib.get_logger("test.access"),
+    service_logger=logger,
+)
+access_middleware = access.make_django_middleware()

tests/django_test_project/django_test_project/settings.py

@@ -50,6 +50,7 @@
     "django.contrib.messages.middleware.MessageMiddleware",
     "django.middleware.clickjacking.XFrameOptionsMiddleware",
     "tests.django_test_project.django_test_project.authz.authz_middleware",
+    "tests.django_test_project.django_test_project.logger.access_middleware",
 ]
 
 ROOT_URLCONF = "tests.django_test_project.django_test_project.urls"

tests/test_platform_django.py

@@ -1,5 +1,6 @@
 import pytest
 import responses
+import structlog.stdlib
 from django.http import JsonResponse
 from django.test import Client
 from tests.django_test_project.django_test_project.authz import authz
@@ -56,3 +57,12 @@ def test_disabled(client: Client):
     authz._enabled = False
     r = client.post("/post-private", data=TEST_AUTHZ_VALID_POST_BODY, content_type="application/json")
     assert r.status_code == 200
+
+
+def test_django_access_logger_middleware_init():
+    from bento_lib.logging.structured.django import BentoDjangoAccessLoggerMiddleware
+
+    BentoDjangoAccessLoggerMiddleware(
+        access_logger=structlog.stdlib.get_logger("test.access"),
+        service_logger=structlog.stdlib.get_logger("test.logger"),
+    ).make_django_middleware()