structure the logs (#3188)

Author: JacobCoffee

config/nginx.conf

@@ -14,7 +14,32 @@ http {
 
 	server_tokens off;
 
-	access_log /tmp/logs/nginx/access.log;
+	# $request_time is seconds with millisecond resolution ("0.042", "12.345").
+	map $request_time $request_time_ms {
+		~^0\.0*(?<ms>\d+)$ $ms;
+		~^(?<s>\d+)\.(?<frac>\d+)$ $s$frac;
+		default null;
+	}
+
+	log_format json escape=json '{'
+		'"timestamp":"$time_iso8601",'
+		'"level":"info",'
+		'"logger":"nginx.access",'
+		'"event":"$request_method $request_uri",'
+		'"method":"$request_method",'
+		'"path":"$uri",'
+		'"query":"$args",'
+		'"status":$status,'
+		'"bytes":$body_bytes_sent,'
+		'"duration_ms":$request_time_ms,'
+		'"upstream_response_time":"$upstream_response_time",'
+		'"protocol":"$server_protocol",'
+		'"referer":"$http_referer",'
+		'"user_agent":"$http_user_agent",'
+		'"request_id":"$request_id"'
+	'}';
+
+	access_log /tmp/logs/nginx/access.log json;
 	error_log /tmp/logs/nginx/error.log;
 
 	include mime.types;
@@ -343,6 +368,7 @@ http {
 
                 location /downloads/ {
                         proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
+                        proxy_set_header X-Request-ID $request_id;
                         proxy_set_header Host $http_host;
                         proxy_redirect off;
                         add_header Cache-Control "max-age=604800, public";
@@ -353,6 +379,7 @@ http {
 
 		location / {
 			proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
+			proxy_set_header X-Request-ID $request_id;
 			proxy_set_header Host $http_host;
 			proxy_redirect off;
 			proxy_pass http://app_server;

gunicorn.conf

@@ -12,7 +12,7 @@ keepalive = 2
 errorlog = '-'
 loglevel = 'info'
 accesslog = '-'
-access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
+logger_class = 'pydotorg.gunicorn_logging.JSONLogger'
 
 control_socket_disable = True
 

pydotorg/celery.py

@@ -3,6 +3,7 @@
 import os
 
 from celery import Celery
+from celery.signals import setup_logging
 from django.core import management
 
 os.environ.setdefault("DJANGO_SETTINGS_MODULE", "pydotorg.settings.local")
@@ -11,6 +12,15 @@
 app.config_from_object("django.conf:settings", namespace="CELERY")
 
 
+@setup_logging.connect
+def configure_logging(**kwargs):
+    """Use Django's LOGGING for worker and beat instead of Celery's own handlers."""
+    from django.conf import settings
+    from django.utils.log import configure_logging as configure_django_logging
+
+    configure_django_logging(settings.LOGGING_CONFIG, settings.LOGGING)
+
+
 @app.task(bind=True)
 def run_management_command(self, command_name, args, kwargs):
     """Execute a Django management command as an async Celery task."""

pydotorg/gunicorn_logging.py

@@ -0,0 +1,50 @@
+"""Gunicorn logger that writes error and access logs as JSON lines.
+
+Enabled via ``logger_class`` in ``gunicorn.conf``. Kept apart from
+``pydotorg.logs`` because gunicorn is only installed with the ``prod`` extra.
+"""
+
+from gunicorn import glogging
+
+from pydotorg.logs import json_formatter
+
+
+class JSONLogger(glogging.Logger):
+    """Gunicorn logger rendering through ``pydotorg.logs.json_formatter``."""
+
+    def setup(self, cfg):
+        """Configure gunicorn's handlers, then swap their formatters for JSON."""
+        super().setup(cfg)
+        formatter = json_formatter()
+        for log in (self.error_log, self.access_log):
+            for handler in log.handlers:
+                if getattr(handler, "_gunicorn", False):
+                    handler.setFormatter(formatter)
+
+    def access(self, resp, req, environ, request_time):
+        """Log one request with method, path, status, and duration as fields."""
+        if not self.access_log_enabled:
+            return
+        try:
+            status = resp.status
+            if isinstance(status, str):
+                status = status.split(None, 1)[0]
+            method = environ["REQUEST_METHOD"]
+            # gunicorn's error path passes a minimal environ: no PATH_INFO, QUERY_STRING, or HTTP_*.
+            fields = {
+                "method": method,
+                "path": environ.get("PATH_INFO", getattr(req, "path", "")),
+                "query": environ.get("QUERY_STRING", getattr(req, "query", "")),
+                "status": int(status),
+                "bytes": getattr(resp, "sent", None),
+                "duration_ms": round(request_time.total_seconds() * 1000, 3),
+                "protocol": environ.get("SERVER_PROTOCOL"),
+                "referer": environ.get("HTTP_REFERER", ""),
+                "user_agent": environ.get("HTTP_USER_AGENT", ""),
+                # Set by nginx; django-structlog binds the same value to app log lines.
+                "request_id": environ.get("HTTP_X_REQUEST_ID")
+                or next((value for name, value in getattr(req, "headers", ()) if name == "X-REQUEST-ID"), ""),
+            }
+            self.access_log.info("%s %s", method, environ["RAW_URI"], extra=fields)
+        except Exception:  # noqa: BLE001 - mirror gunicorn: never let logging break a response
+            self.exception("Failed to write access log")

pydotorg/logs.py

@@ -0,0 +1,60 @@
+"""structlog setup shared by Django, Celery, and gunicorn.
+
+Both structlog loggers and stdlib ``logging`` records (Django, Celery, gunicorn,
+third-party libraries) render through ``structlog.stdlib.ProcessorFormatter``:
+``json_formatter`` for production (one JSON object per line) and
+``console_formatter`` for local development.
+"""
+
+import structlog
+
+# Applied to every entry. Context bound by django-structlog's RequestMiddleware
+# (request_id, user_id) is merged into stdlib records too.
+_SHARED_PROCESSORS = [
+    structlog.contextvars.merge_contextvars,
+    structlog.stdlib.add_log_level,
+    structlog.stdlib.add_logger_name,
+    structlog.processors.TimeStamper(fmt="iso", utc=True),
+    structlog.processors.StackInfoRenderer(),
+]
+
+# Stdlib records also carry fields passed via ``extra=``.
+_FOREIGN_PRE_CHAIN = [*_SHARED_PROCESSORS, structlog.stdlib.ExtraAdder()]
+
+
+def configure_structlog():
+    """Route structlog loggers through stdlib ``logging`` so ``LOGGING`` picks the renderer."""
+    structlog.configure(
+        processors=[
+            structlog.stdlib.filter_by_level,
+            *_SHARED_PROCESSORS,
+            structlog.stdlib.PositionalArgumentsFormatter(),
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
+
+def json_formatter():
+    """Return a formatter that writes each entry as one JSON object."""
+    return structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=_FOREIGN_PRE_CHAIN,
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            structlog.processors.format_exc_info,
+            structlog.processors.JSONRenderer(),
+        ],
+    )
+
+
+def console_formatter():
+    """Return a formatter that writes aligned, human-readable lines."""
+    return structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=_FOREIGN_PRE_CHAIN,
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            structlog.dev.ConsoleRenderer(),
+        ],
+    )

pydotorg/settings/base.py

@@ -1,12 +1,14 @@
 """Base Django settings for the python.org project."""
 
+import logging
 from pathlib import Path
 
 from csp.constants import NONCE, SELF, UNSAFE_INLINE
 from decouple import config
 from dj_database_url import parse as dj_database_url_parser
 from django.contrib.messages import constants
 
+from pydotorg.logs import configure_structlog
 from pydotorg.markup import MARKUP_FIELD_TYPES  # noqa: F401 - read by django-markupfield via settings
 from pydotorg.settings.pipeline import PIPELINE  # noqa: F401 - accessed by django-pipeline via settings
 
@@ -158,6 +160,7 @@
     "pydotorg.middleware.AdminNoCaching",
     "pydotorg.middleware.GlobalSurrogateKey",
     "django.contrib.auth.middleware.AuthenticationMiddleware",
+    "django_structlog.middlewares.RequestMiddleware",
     "django.contrib.messages.middleware.MessageMiddleware",
     "waffle.middleware.WaffleMiddleware",
     "django.middleware.clickjacking.XFrameOptionsMiddleware",
@@ -186,6 +189,7 @@
     "django.contrib.admin",
     "django.contrib.admindocs",
     "django_celery_beat",
+    "django_structlog",
     "django_translation_aliases",
     "pipeline",
     "sitetree",
@@ -239,22 +243,47 @@
     "version": 1,
     "disable_existing_loggers": False,
     "filters": {"require_debug_false": {"()": "django.utils.log.RequireDebugFalse"}},
+    "formatters": {
+        "console": {"()": "pydotorg.logs.console_formatter"},
+        "json": {"()": "pydotorg.logs.json_formatter"},
+    },
     "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+            "stream": "ext://sys.stdout",
+            "formatter": "console",
+        },
         "mail_admins": {
             "level": "ERROR",
             "filters": ["require_debug_false"],
             "class": "django.utils.log.AdminEmailHandler",
-        }
+        },
     },
+    "root": {"handlers": ["console"], "level": "WARNING"},
     "loggers": {
+        # Replaces Django's default console handler so records reach stdout once, via root.
+        "django": {"handlers": ["mail_admins"], "level": "INFO"},
+        # Emails only; django-structlog's request_failed puts the traceback on stdout with request context.
         "django.request": {
             "handlers": ["mail_admins"],
             "level": "ERROR",
-            "propagate": True,
+            "propagate": False,
         },
+        "django_structlog": {"level": "INFO"},
+        "apps": {"level": "INFO"},
+        "pydotorg": {"level": "INFO"},
+        "celery": {"level": "INFO"},
     },
 }
 
+configure_structlog()
+
+# nginx and gunicorn already log every request; keep only 5xx and request_failed from django-structlog.
+DJANGO_STRUCTLOG_STATUS_DEFAULT_LOG_LEVEL = logging.DEBUG
+DJANGO_STRUCTLOG_STATUS_4XX_LOG_LEVEL = logging.DEBUG
+# Client IPs were never logged; keep it that way.
+DJANGO_STRUCTLOG_IP_LOGGING_ENABLED = False
+
 ### Honeypot
 HONEYPOT_FIELD_NAME = "email_body_text"
 HONEYPOT_VALUE = "write your message"

pydotorg/settings/cabotage.py

@@ -8,6 +8,8 @@
 
 DEBUG = TEMPLATE_DEBUG = False
 
+LOGGING["handlers"]["console"]["formatter"] = "json"
+
 DATABASE_CONN_MAX_AGE = 600
 DATABASES["default"]["CONN_MAX_AGE"] = DATABASE_CONN_MAX_AGE
 

pyproject.toml

@@ -31,6 +31,7 @@ dependencies = [
     "django-pipeline==4.1.0",
     "django-polymorphic==4.11.7",
     "django-sitetree==1.18.1",
+    "django-structlog==10.1.0",
     "django-tastypie==0.15.1",
     "django-translation-aliases==0.1.0",
     "django-waffle==5.0.0",
@@ -55,6 +56,7 @@ dependencies = [
     "python3-openid==3.2.0",
     "requests>=2.34.2",
     "sorl-thumbnail==13.1.0",
+    "structlog==26.1.0",
     "unidecode==1.4.0",
 ]
 [project.optional-dependencies]