feat(Backend): PRWLR-3990 Add custom logging (#6)

* chore: PRWLR-4022 add django-cors-headers

* chore: PRWLR-4022 configure basic CORS

* feat: PRWLR-4022 add drf-spectacular and spec/docs endpoints

* build: PRWLR-4022 add basic docker development deployment

* chore: PRWLR-4022 update schema generation

* chore: PRWLR-4022 bump required Python version to 3.12

* feat: PRWLR-3990 add basic custom Django logging

* feat: PRWLR-3990 add tasks logger

* chore: PRWLR-3990 update API logging middleware to follow updated syntax

* docs: PRWLR-3990 add docstring for APILoggingMiddleware class

* chore: PRWLR-3990 add testing dependencies to poetry

* test(API): PRWLR-3990 add new middleware unit tests and base setup

* feat(API, Backend): PRWLR-3990 add NDJSONFormatter and transaction_id

* feat(API): PRWLR-3990 add dev/test model, views and urls

* chore(backend): PRWLR-3990 refactor logging settings and modules

* chore(backend): PRWLR-3990 add BackendLogger enum and refactor logging modules

* chore(backend): PRWLR-3990 refactor module importing

* style(backend): PRWLR-3990 remove extra endlines

* chore: PRWLR-3990 update poetry.lock

* chore: PRWLR-3990 run pre-commit

src/backend/api/middleware.py

@@ -0,0 +1,37 @@
+import logging
+import time
+
+from backend.custom_logging import BackendLogger
+
+
+class APILoggingMiddleware:
+    """
+    Middleware for logging API requests.
+
+    This middleware logs details of API requests, including the typical request metadata among other useful information.
+
+    Args:
+        get_response (Callable): A callable to get the response, typically the next middleware or view.
+    """
+
+    def __init__(self, get_response):
+        self.get_response = get_response
+        self.logger = logging.getLogger(BackendLogger.API)
+
+    def __call__(self, request):
+        request_start_time = time.time()
+
+        response = self.get_response(request)
+        duration = time.time() - request_start_time
+        self.logger.info(
+            "",
+            extra={
+                "method": request.method,
+                "path": request.path,
+                "query_params": request.GET.dict(),
+                "status_code": response.status_code,
+                "duration": duration,
+            },
+        )
+
+        return response

src/backend/api/migrations/0001_initial.py

@@ -0,0 +1,27 @@
+# Generated by Django 5.0.6 on 2024-07-04 16:53
+
+from django.db import migrations, models
+
+
+class Migration(migrations.Migration):
+    initial = True
+
+    dependencies = []
+
+    operations = [
+        migrations.CreateModel(
+            name="TestModel",
+            fields=[
+                (
+                    "id",
+                    models.BigAutoField(
+                        auto_created=True,
+                        primary_key=True,
+                        serialize=False,
+                        verbose_name="ID",
+                    ),
+                ),
+                ("name", models.CharField(max_length=100)),
+            ],
+        ),
+    ]

src/backend/api/models.py

@@ -1 +1,10 @@
-# Create your models here.
+from django.db import models
+
+
+class TestModel(models.Model):
+    """To delete.
+
+    Use this model for development/testing purposes.
+    """
+
+    name = models.CharField(max_length=100)

src/backend/api/serializers.py

@@ -0,0 +1,14 @@
+from rest_framework import serializers
+
+from api.models import TestModel
+
+
+class TestModelSerializer(serializers.ModelSerializer):
+    """To delete.
+
+    Use this serializer for development/testing purposes.
+    """
+
+    class Meta:
+        model = TestModel
+        fields = "__all__"

src/backend/api/tests/test_middleware.py

@@ -0,0 +1,26 @@
+from unittest.mock import patch, Mock, ANY
+
+
+@patch("logging.getLogger")
+def test_api_logger_middleware(mock_get_logger, client):
+    mock_logger = Mock()
+    mock_get_logger.side_effect = lambda name: mock_logger if name == "api" else Mock()
+    request_method = "GET"
+    request_path = "/this_path_does_not_exist"
+    api_logger = "api"
+
+    response = getattr(client, request_method.lower())(request_path)
+
+    mock_get_logger.assert_any_call(api_logger)
+    mock_logger.info.assert_called_once_with(
+        "",
+        extra={
+            "method": request_method,
+            "path": request_path,
+            "query_params": {},
+            "status_code": response.status_code,
+            "duration": ANY,
+        },
+    )
+
+    assert isinstance(mock_logger.info.call_args[1]["extra"]["duration"], float)

src/backend/api/urls/v1/urls.py

@@ -1,7 +1,16 @@
 from django.urls import path
 from drf_spectacular.views import SpectacularAPIView, SpectacularRedocView
 
+from api.views.v1 import views
+
 urlpatterns = [
     path("schema", SpectacularAPIView.as_view(), name="schema"),
     path("docs", SpectacularRedocView.as_view(url_name="schema"), name="docs"),
+    # To delete. Use this url for development/testing purposes
+    path("test", views.TestModelCreateView.as_view(), name="test-list"),
+    path(
+        "test/<int:pk>/",
+        views.TestModelRetrieveUpdateDestroyView.as_view(),
+        name="test-detail",
+    ),
 ]

src/backend/api/views/v1/views.py

@@ -0,0 +1,14 @@
+from rest_framework import generics
+
+from api.models import TestModel
+from api.serializers import TestModelSerializer
+
+
+class TestModelCreateView(generics.ListCreateAPIView):
+    queryset = TestModel.objects.all()
+    serializer_class = TestModelSerializer
+
+
+class TestModelRetrieveUpdateDestroyView(generics.RetrieveUpdateDestroyAPIView):
+    queryset = TestModel.objects.all()
+    serializer_class = TestModelSerializer

src/backend/backend/custom_logging.py

@@ -0,0 +1,167 @@
+import json
+import logging
+from enum import StrEnum
+
+from django_guid.log_filters import CorrelationId
+
+
+class BackendLogger(StrEnum):
+    DJANGO = "django"
+    SECURITY = "django.security"
+    DB = "django.db"
+    API = "api"
+    TASKS = "tasks"
+
+
+# Formatters
+
+
+class NDJSONFormatter(logging.Formatter):
+    """NDJSON custom formatter for logging messages.
+
+    If available, it will include all kind of API request metadata.
+    """
+
+    def format(self, record):
+        log_record = {
+            "timestamp": self.formatTime(record, self.datefmt),
+            "level": record.levelname,
+            "message": record.getMessage(),
+            "logger": record.name,
+            "module": record.module,
+            "pathname": record.pathname,
+            "lineno": record.lineno,
+            "funcName": record.funcName,
+            "process": record.process,
+            "thread": record.thread,
+            "transaction_id": record.transaction_id
+            if hasattr(record, "transaction_id")
+            else "N/A",
+        }
+
+        # Add REST API extra fields
+        if hasattr(record, "method"):
+            log_record["method"] = record.method
+        if hasattr(record, "path"):
+            log_record["path"] = record.path
+        if hasattr(record, "query_params"):
+            log_record["query_params"] = record.query_params
+        if hasattr(record, "duration"):
+            log_record["duration"] = record.duration
+        if hasattr(record, "status_code"):
+            log_record["status_code"] = record.status_code
+
+        if record.exc_info:
+            log_record["exc_info"] = self.formatException(record.exc_info)
+
+        return json.dumps(log_record)
+
+
+# Filters
+
+
+class TransactionIdFilter(CorrelationId):
+    """Logging filter class.
+
+    Used to override the `correlation_id_field` parameter in the parent class to use a different name.
+    """
+
+    CORRELATION_ID_FIELD = "transaction_id"
+
+    def __init__(self):
+        super().__init__(correlation_id_field=self.CORRELATION_ID_FIELD)
+
+
+# Logging settings
+
+LOGGING = {
+    "version": 1,
+    "disable_existing_loggers": True,
+    "filters": {"transaction_id": {"()": TransactionIdFilter}},
+    "formatters": {
+        "ndjson": {
+            "()": NDJSONFormatter,
+            "datefmt": "%Y-%m-%d %H:%M:%S",
+        },
+        "django": {
+            "format": "{asctime} [{name}] {levelname}: ({module}) {message}",
+            "style": "{",
+        },
+        "api": {
+            "format": '{asctime} [{name}] {levelname}: "{method} {path}" with parameters {query_params} done in '
+            "{duration}s: {status_code}",
+            "style": "{",
+        },
+        "db": {
+            "format": "{asctime} [{name}] {levelname}: {message}",
+            "style": "{",
+        },
+        "security": {
+            "format": "{asctime} [{name}] {levelname}: {message}",
+            "style": "{",
+        },
+        "tasks": {
+            "format": "{asctime} [{name}] {levelname}: {message}",
+            "style": "{",
+        },
+    },
+    "handlers": {
+        "django_console": {
+            "level": "INFO",
+            "class": "logging.StreamHandler",
+            "formatter": "ndjson",
+            "filters": ["transaction_id"],
+        },
+        "api_console": {
+            "level": "INFO",
+            "class": "logging.StreamHandler",
+            "formatter": "ndjson",
+            "filters": ["transaction_id"],
+        },
+        "db_console": {
+            "level": "DEBUG",
+            "class": "logging.StreamHandler",
+            "formatter": "ndjson",
+            "filters": ["transaction_id"],
+        },
+        "security_console": {
+            "level": "INFO",
+            "class": "logging.StreamHandler",
+            "formatter": "ndjson",
+            "filters": ["transaction_id"],
+        },
+        "tasks_console": {
+            "level": "INFO",
+            "class": "logging.StreamHandler",
+            "formatter": "ndjson",
+            "filters": ["transaction_id"],
+        },
+    },
+    "loggers": {
+        BackendLogger.DJANGO: {
+            "handlers": ["django_console"],
+            "level": "INFO",
+            "propagate": True,
+        },
+        BackendLogger.DB: {
+            "handlers": ["db_console"],
+            "level": "DEBUG",
+            "propagate": False,
+        },
+        BackendLogger.SECURITY: {
+            "handlers": ["security_console"],
+            "level": "INFO",
+            "propagate": False,
+        },
+        BackendLogger.API: {
+            "handlers": ["api_console"],
+            "level": "INFO",
+            "propagate": False,
+        },
+        BackendLogger.TASKS: {
+            "handlers": ["tasks_console"],
+            "level": "INFO",
+            "propagate": False,
+        },
+    },
+}

src/backend/backend/settings.py

@@ -1,17 +1,7 @@
-"""
-Django settings for backend project.
-
-Generated by 'django-admin startproject' using Django 5.0.6.
-
-For more information on this file, see
-https://docs.djangoproject.com/en/5.0/topics/settings/
-
-For the full list of settings and their values, see
-https://docs.djangoproject.com/en/5.0/ref/settings/
-"""
-
 from pathlib import Path
 
+from backend.custom_logging import LOGGING  # noqa
+
 # Build paths inside the project like this: BASE_DIR / 'subdir'.
 BASE_DIR = Path(__file__).resolve().parent.parent
 
@@ -41,9 +31,11 @@ INSTALLED_APPS = [
     "rest_framework",
     "corsheaders",
     "drf_spectacular",
+    "django_guid",
 ]
 
 MIDDLEWARE = [
+    "django_guid.middleware.guid_middleware",
     "django.middleware.security.SecurityMiddleware",
     "django.contrib.sessions.middleware.SessionMiddleware",
     "corsheaders.middleware.CorsMiddleware",
@@ -52,6 +44,7 @@ MIDDLEWARE = [
     "django.contrib.auth.middleware.AuthenticationMiddleware",
     "django.contrib.messages.middleware.MessageMiddleware",
     "django.middleware.clickjacking.XFrameOptionsMiddleware",
+    "api.middleware.APILoggingMiddleware",
 ]
 
 CORS_ALLOWED_ORIGINS = ["http://localhost", "http://127.0.0.1"]
@@ -87,7 +80,6 @@ SPECTACULAR_SETTINGS = {
 
 WSGI_APPLICATION = "backend.wsgi.application"
 
-
 # Database
 # https://docs.djangoproject.com/en/5.0/ref/settings/#databases
 
@@ -98,6 +90,15 @@ DATABASES = {
     }
 }
 
+DJANGO_GUID = {
+    "GUID_HEADER_NAME": "Transaction-ID",
+    "VALIDATE_GUID": True,
+    "RETURN_HEADER": True,
+    "EXPOSE_HEADER": True,
+    "INTEGRATIONS": [],
+    "IGNORE_URLS": [],
+    "UUID_LENGTH": 32,
+}
 
 # Password validation
 # https://docs.djangoproject.com/en/5.0/ref/settings/#auth-password-validators

src/backend/conftest.py

@@ -0,0 +1,8 @@
+import logging
+
+import pytest
+
+
+@pytest.fixture(autouse=True)
+def disable_logging():
+    logging.disable(logging.CRITICAL)

src/backend/pytest.ini

@@ -0,0 +1,3 @@
+[pytest]
+DJANGO_SETTINGS_MODULE = backend.settings
+addopts = -rP