Convert server access log to structured context logging

Replace Apache Combined Log Format with structured key-value/JSON output
using the existing LOG_FORMAT formatter system. Access log fields are
fully configurable via SERVER_ACCESS_LOG_FIELDS, with a verbose default
for production and a minimal set in plain dev.

Author: davegaeddert

plain-dev/plain/dev/core.py

@@ -69,6 +69,7 @@ def setup(
         self.plain_env = {
             "PYTHONUNBUFFERED": "true",
             "PLAIN_DEV": "true",
+            "PLAIN_SERVER_ACCESS_LOG_FIELDS": '["method", "url", "status", "duration_ms", "size"]',
             "FORCE_COLOR": "1",
             "PYTHONWARNINGS": "default::DeprecationWarning,default::PendingDeprecationWarning",
             **os.environ,

plain/plain/logs/README.md

@@ -195,6 +195,20 @@ Valid log levels: `DEBUG`, `INFO`, `WARNING`, `ERROR`, `CRITICAL`
 
 The server writes access logs to a separate `plain.server.access` logger that always outputs to stdout, regardless of the `LOG_STREAM` setting. This keeps access logs separate from application logs.
 
+Access logs use the same `LOG_FORMAT` setting as the app logger, producing structured output with request fields:
+
+```
+[INFO] Request method=GET path="/" status=200 duration_ms=12 size=1234 ip="127.0.0.1" user_agent="Mozilla/5.0..." referer="https://example.com"
+```
+
+In JSON format:
+
+```json
+{"timestamp": "2024-01-15 10:30:00,123", "level": "INFO", "message": "Request", "logger": "plain.server.access", "method": "GET", "path": "/", "status": 200, "duration_ms": 12, "size": 1234, "ip": "127.0.0.1", "user_agent": "Mozilla/5.0...", "referer": "https://example.com"}
+```
+
+Additional fields beyond the defaults are controlled by `SERVER_ACCESS_LOG_FIELDS` (see the server docs).
+
 Access logging is controlled by the `SERVER_ACCESS_LOG` setting (see the server docs). Individual responses can opt out by setting `response.log_access = False`.
 
 ## FAQs

plain/plain/logs/configure.py

@@ -30,6 +30,19 @@ def attach_log_handlers(
     logger.addHandler(warning_handler)
 
 
+def _create_app_formatter(app_log_format: str) -> logging.Formatter:
+    """Create a formatter based on the app log format setting."""
+    match app_log_format:
+        case "json":
+            return JSONFormatter("%(json)s")
+        case "keyvalue":
+            return KeyValueFormatter("[%(levelname)s] %(message)s %(keyvalue)s")
+        case _:
+            raise ValueError(
+                f"Invalid LOG_FORMAT: {app_log_format!r}. Must be 'keyvalue' or 'json'."
+            )
+
+
 def configure_logging(
     *,
     plain_log_level: int | str,
@@ -66,15 +79,7 @@ def configure_logging(
     app_logger.propagate = False
 
     # Determine formatter based on app_log_format
-    match app_log_format:
-        case "json":
-            formatter = JSONFormatter("%(json)s")
-        case "keyvalue":
-            formatter = KeyValueFormatter("[%(levelname)s] %(message)s %(keyvalue)s")
-        case _:
-            raise ValueError(
-                f"Invalid LOG_FORMAT: {app_log_format!r}. Must be 'keyvalue' or 'json'."
-            )
+    formatter = _create_app_formatter(app_log_format)
 
     attach_log_handlers(
         logger=app_logger,
@@ -100,5 +105,5 @@ def configure_logging(
     server_access_logger.propagate = False
     if had_handlers:
         handler = logging.StreamHandler(sys.stdout)
-        handler.setFormatter(logging.Formatter("%(message)s"))
+        handler.setFormatter(_create_app_formatter(app_log_format))
         server_access_logger.addHandler(handler)

plain/plain/runtime/global_settings.py

@@ -179,6 +179,17 @@
 SERVER_TIMEOUT: int = 30
 SERVER_MAX_REQUESTS: int = 0
 SERVER_ACCESS_LOG: bool = True
+SERVER_ACCESS_LOG_FIELDS: list[str] = [
+    "method",
+    "path",
+    "query",
+    "status",
+    "duration_ms",
+    "size",
+    "ip",
+    "user_agent",
+    "referer",
+]
 SERVER_GRACEFUL_TIMEOUT: int = 30
 SERVER_SENDFILE: bool = True
 SERVER_FORWARDED_ALLOW_IPS: str = (

plain/plain/server/README.md

@@ -79,6 +79,7 @@ SERVER_THREADS = 4
 SERVER_TIMEOUT = 30
 SERVER_MAX_REQUESTS = 0      # 0 = disabled
 SERVER_ACCESS_LOG = True
+SERVER_ACCESS_LOG_FIELDS = ["method", "path", "query", "status", "duration_ms", "size", "ip", "user_agent", "referer"]
 SERVER_GRACEFUL_TIMEOUT = 30
 SERVER_SENDFILE = True
 SERVER_FORWARDED_ALLOW_IPS = "127.0.0.1,::1"
@@ -88,6 +89,34 @@ Settings can also be set via environment variables with the `PLAIN_` prefix (e.g
 
 The `WEB_CONCURRENCY` environment variable is supported as an alias for `SERVER_WORKERS`.
 
+### Access log format
+
+Access logs use the same `LOG_FORMAT` setting as the app logger, so they produce structured output in key-value or JSON format:
+
+```
+[INFO] Request method=GET path="/" status=200 duration_ms=12 size=1234 ip="127.0.0.1" user_agent="Mozilla/5.0..." referer="https://example.com"
+```
+
+See the [logs docs](../logs/README.md) for details on output formats.
+
+### Access log fields
+
+`SERVER_ACCESS_LOG_FIELDS` controls exactly which fields appear in access log entries. The default includes all common fields:
+
+```python
+# settings.py (default)
+SERVER_ACCESS_LOG_FIELDS = [
+    "method", "path", "query", "status", "duration_ms", "size",
+    "ip", "user_agent", "referer",
+]
+```
+
+Available fields: `method`, `path`, `url`, `query`, `status`, `duration_ms`, `size`, `ip`, `user_agent`, `referer`, `protocol`.
+
+Use `url` for a combined path + query string (e.g., `url="/search?q=hello"`). Use `path` and `query` separately for production log aggregation.
+
+In development, `plain dev` sets a minimal field list for cleaner output (`method`, `url`, `status`, `duration_ms`, `size`). Set `PLAIN_SERVER_ACCESS_LOG_FIELDS` in your environment to override.
+
 ### Per-response access log control
 
 Individual responses can opt out of the access log by setting `log_access = False` on the response object. This is useful for noisy endpoints like health checks or asset serving.

plain/plain/server/glogging.py

@@ -6,44 +6,23 @@
 # See the LICENSE for more information.
 #
 # Vendored and modified for Plain.
-import base64
-import binascii
 import datetime
 import logging
-import os
 import sys
-import time
 import traceback
 from typing import Any
 
+from plain.logs.formatters import KeyValueFormatter
+
 # Module-level loggers
 log = logging.getLogger("plain.server")
 access_log = logging.getLogger("plain.server.access")
 
-# Access log format (Apache Combined Log Format)
-ACCESS_LOG_FORMAT = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"'
-
-
-class SafeAtoms(dict[str, Any]):
-    def __init__(self, atoms: dict[str, Any]) -> None:
-        dict.__init__(self)
-        for key, value in atoms.items():
-            if isinstance(value, str):
-                self[key] = value.replace('"', '\\"')
-            else:
-                self[key] = value
-
-    def __getitem__(self, k: str) -> Any:
-        if k.startswith("{"):
-            kl = k.lower()
-            if kl in self:
-                return super().__getitem__(kl)
-            else:
-                return "-"
-        if k in self:
-            return super().__getitem__(k)
-        else:
-            return "-"
+# Maps field names that come from request headers
+_HEADER_FIELDS = {
+    "user_agent": "USER-AGENT",
+    "referer": "REFERER",
+}
 
 
 def setup_bootstrap_logging(accesslog: bool) -> None:
@@ -70,7 +49,7 @@ def setup_bootstrap_logging(accesslog: bool) -> None:
     if accesslog:
         _set_handler(
             access_log,
-            logging.Formatter("%(message)s"),
+            KeyValueFormatter("[%(levelname)s] %(message)s %(keyvalue)s"),
             stream=sys.stdout,
         )
 
@@ -91,91 +70,62 @@ def _set_handler(
     logger.addHandler(h)
 
 
+def _get_header(req: Any, header_name: str) -> str:
+    """Look up a header value from the request's header list."""
+    for name, value in req.headers:
+        if name == header_name:
+            return value
+    return ""
+
+
 def log_access(
     resp: Any,
     req: Any,
     request_time: datetime.timedelta,
 ) -> None:
     """Log an access entry for a completed request."""
-    if not access_log.handlers:
+    if not access_log.handlers or not access_log.isEnabledFor(logging.INFO):
         return
 
-    safe_atoms = SafeAtoms(_build_atoms(resp, req, request_time))
-
-    try:
-        access_log.info(ACCESS_LOG_FORMAT, safe_atoms)
-    except Exception:
-        log.error(traceback.format_exc())
-
+    from plain.runtime import settings
 
-def _build_atoms(
-    resp: Any,
-    req: Any,
-    request_time: datetime.timedelta,
-) -> dict[str, Any]:
-    """Build log atoms from server response and request objects."""
     status = resp.status
     if isinstance(status, str):
         status = status.split(None, 1)[0]
 
-    protocol = f"HTTP/{req.version[0]}.{req.version[1]}"
-
-    # Get client IP from the server request's peer address
-    if isinstance(req.peer_addr, tuple):
-        remote_addr = req.peer_addr[0]
-    elif isinstance(req.peer_addr, str):
-        remote_addr = req.peer_addr
-    else:
-        remote_addr = "-"
-
-    atoms: dict[str, Any] = {}
-
-    # Add request headers as {name}i atoms
-    atoms.update({f"{{{k.lower()}}}i": v for k, v in req.headers})
-
-    # Add response headers as {name}o atoms
-    resp_headers = resp.headers
-    if hasattr(resp_headers, "items"):
-        resp_headers = resp_headers.items()
-    atoms.update({f"{{{k.lower()}}}o": v for k, v in resp_headers})
-
-    atoms.update(
-        {
-            "h": remote_addr,
-            "l": "-",
-            "u": _get_user(atoms) or "-",
-            "t": time.strftime("[%d/%b/%Y:%H:%M:%S %z]"),
-            "r": f"{req.method} {req.uri} {protocol}",
-            "s": status,
-            "m": req.method,
-            "U": req.path,
-            "q": req.query,
-            "H": protocol,
-            "b": getattr(resp, "sent", None) is not None and str(resp.sent) or "-",
-            "B": getattr(resp, "sent", None),
-            "f": atoms.get("{referer}i", "-"),
-            "a": atoms.get("{user-agent}i", "-"),
-            "T": request_time.seconds,
-            "D": (request_time.seconds * 1000000) + request_time.microseconds,
-            "M": (request_time.seconds * 1000) + int(request_time.microseconds / 1000),
-            "L": f"{request_time.seconds}.{request_time.microseconds:06d}",
-            "p": f"<{os.getpid()}>",
-        }
-    )
+    context: dict[str, Any] = {}
+
+    for field in settings.SERVER_ACCESS_LOG_FIELDS:
+        if field == "method":
+            context["method"] = req.method
+        elif field == "path":
+            context["path"] = req.path
+        elif field == "status":
+            context["status"] = int(status)
+        elif field == "duration_ms":
+            context["duration_ms"] = int(request_time.total_seconds() * 1000)
+        elif field == "size":
+            context["size"] = getattr(resp, "sent", None) or 0
+        elif field == "ip":
+            if isinstance(req.peer_addr, tuple):
+                context["ip"] = req.peer_addr[0]
+            elif isinstance(req.peer_addr, str):
+                context["ip"] = req.peer_addr
+            else:
+                context["ip"] = ""
+        elif field == "url":
+            if req.query:
+                context["url"] = f"{req.path}?{req.query}"
+            else:
+                context["url"] = req.path
+        elif field == "query":
+            context["query"] = req.query or ""
+        elif field == "protocol":
+            context["protocol"] = f"HTTP/{req.version[0]}.{req.version[1]}"
+        elif header_name := _HEADER_FIELDS.get(field):
+            context[field] = _get_header(req, header_name)
 
-    return atoms
-
-
-def _get_user(atoms: dict[str, Any]) -> str | None:
-    """Extract username from Basic auth in request headers."""
-    user = None
-    http_auth = atoms.get("{authorization}i")
-    if http_auth and http_auth.lower().startswith("basic"):
-        auth = http_auth.split(" ", 1)
-        if len(auth) == 2:
-            try:
-                auth = base64.b64decode(auth[1].strip().encode("utf-8"))
-                user = auth.split(b":", 1)[0].decode("UTF-8")
-            except (TypeError, binascii.Error, UnicodeDecodeError) as exc:
-                log.debug("Couldn't get username: %s", exc)
-    return user
+    try:
+        access_log.info("Request", extra={"context": context})
+    except Exception:
+        log.error(traceback.format_exc())