Log structured fields through a logger adapter

app.logger.info("message", key=value) appends the keyword arguments as
JSON encoded fields, so callers no longer format the values themselves.
All log calls use fixed messages and put variable values into fields.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

max/app.py

@@ -67,7 +67,7 @@ def main():
     init_auth(app)
     init_routes(app)
     init_security_headers(app)
-    app.logger.info("Max initialized, version %s.", app.config["VERSION"])
+    app.logger.info("Max initialized", version=app.config["VERSION"])
     return app
 
 

max/audit.py

@@ -1,11 +1,9 @@
 from flask import current_app, request
 
-from max.log_format import format_log_fields
-
 
 def audit(event, actor=None, target=None, **fields):
     """
-    Logs a security relevant event as one line, starting with "audit". actor is the
+    Logs a security relevant event as one line with the message "audit". actor is the
     acting user, None for anonymous requests. target is the affected user, if any.
     """
     values = dict(
@@ -17,4 +15,4 @@ def audit(event, actor=None, target=None, **fields):
     if target is not None:
         values.update(target_user_id=target.id, target_email=target.email)
     values.update(fields)
-    current_app.logger.info("audit %s", format_log_fields(**values))
+    current_app.logger.info("audit", **values)

max/auth/passwords.py

@@ -25,4 +25,4 @@ def rehash_password_if_needed(user, password):
     # check_password accepted the password, so hash_password can hash it. The policy for
     # new passwords does not apply here.
     update_user(user.id, passwordhash=hash_password(password))
-    current_app.logger.info("Rehashed the password of user %s", user.id)
+    current_app.logger.info("Rehashed the password", user_id=user.id)

max/csrf.py

@@ -3,7 +3,6 @@ from functools import wraps
 from flask import request, session
 
 from max.crypto import constant_time_compare, get_random_string
-from max.log_format import format_log_fields
 from max.middlewares import BaseMiddleware, get_real_remote_addr
 
 CSRF_TOKEN_KEY = "csrf_token"
@@ -34,14 +33,12 @@ class CsrfMiddleware(BaseMiddleware):
         # Stateless check, so it also protects routes without a session (login)
         if not self.is_origin_allowed():
             self.app.logger.debug(
-                "Blocked cross-origin request %s",
+                "Blocked cross-origin request",
-                format_log_fields(
                 method=request.method,
                 path=request.path,
                 origin=request.headers.get("Origin"),
                 sec_fetch_site=request.headers.get("Sec-Fetch-Site"),
                 ip=get_real_remote_addr(self.app),
-                ),
             )
             return "Cross-origin request blocked", 403
 

max/db/connection.py

@@ -92,7 +92,7 @@ class Database:
     def add_query(self, query, args=None):
         if args is None:
             args = []
-        self.app.logger.debug('query="%s", args="%s"', query, str(args))
+        self.app.logger.debug("query", query=query, args=args)
         self.query_count += 1
 
     def collect_query_count(self):

max/log.py

@@ -1,3 +1,4 @@
+import json
 import logging
 import sys
 import time
@@ -6,10 +7,49 @@ from logging.config import dictConfig
 from flask import g, request, session
 
 from max.db import database
-from max.log_format import format_log_fields
 from max.middlewares import get_real_remote_addr
 from max.translations import TranslationHandler
 
+# Keyword arguments handled by logging itself, all others become fields
+LOGGING_KWARGS = frozenset(("exc_info", "stack_info", "stacklevel", "extra"))
+
+
+def format_log_fields(**fields):
+    """
+    Formats the fields as "key=value key=value". Values are JSON encoded, so values from
+    the client cannot break the line or add fields.
+    """
+    return " ".join(
+        f"{key}={json.dumps(value, ensure_ascii=False, default=str)}"
+        for key, value in fields.items()
+    )
+
+
+class FieldsLogger(logging.LoggerAdapter):
+    """
+    Turns keyword arguments into fields: logger.info("message", key=value). The message
+    is a fixed text, everything variable goes into the fields.
+    """
+
+    def process(self, msg, kwargs):
+        fields = {
+            key: kwargs.pop(key) for key in list(kwargs) if key not in LOGGING_KWARGS
+        }
+        if fields:
+            kwargs["extra"] = {**kwargs.get("extra", {}), "fields": fields}
+        return msg, kwargs
+
+
+class FieldsFormatter(logging.Formatter):
+    """Appends the fields of a FieldsLogger record to the line"""
+
+    def format(self, record):
+        line = super().format(record)
+        fields = getattr(record, "fields", None)
+        if not fields:
+            return line
+        return f"{line} {format_log_fields(**fields)}"
+
 
 class NoDevServerRequestsFilter(logging.Filter):
     """Drops the request lines of the Werkzeug dev server, the app logs requests itself"""
@@ -23,7 +63,10 @@ def init_logging(app):
         {
             "version": 1,
             "formatters": {
-                "default": {"format": "[%(asctime)s] [%(levelname)s]: %(message)s"}
+                "default": {
+                    "()": FieldsFormatter,
+                    "fmt": "[%(asctime)s] [%(levelname)s]: %(message)s",
+                }
             },
             "handlers": {
                 "stdout": {
@@ -37,6 +80,7 @@ def init_logging(app):
     )
     logger = logging.getLogger(app.name)
     logger.setLevel(logging.DEBUG if app.debug else logging.INFO)
+    app.logger = FieldsLogger(logger)
     if app.debug:
         logging.getLogger("werkzeug").addFilter(NoDevServerRequestsFilter())
 
@@ -63,8 +107,7 @@ def init_request_logging(app):
         time_in_ms = round((time.time() - start) * 1000, 2) if start else None
 
         app.logger.info(
-            "%s",
+            "request",
-            format_log_fields(
             method=request.method,
             url=request.url,
             ip=get_real_remote_addr(app),
@@ -72,12 +115,9 @@ def init_request_logging(app):
             referrer=request.referrer,
             db_queries=database.collect_query_count(),
             status=response.status_code if response is not None else 500,
-                content_length=(
+            content_length=response.content_length if response is not None else None,
-                    response.content_length if response is not None else None
-                ),
             user_id=session.get("user_id"),
             session=session.get_log_id(),
             lang=TranslationHandler.get_language(),
             time_ms=time_in_ms,
-            ),
         )

max/log_format.py

@@ -1,12 +0,0 @@
-import json
-
-
-def format_log_fields(**fields):
-    """
-    Formats the fields as "key=value key=value". Values are JSON encoded, so values from
-    the client cannot break the line or add fields.
-    """
-    return " ".join(
-        f"{key}={json.dumps(value, ensure_ascii=False)}"
-        for key, value in fields.items()
-    )

max/translations.py

@@ -50,7 +50,7 @@ class TranslationHandler:
     @classmethod
     def set_language(cls, language):
         if not cls.is_language_available(language):
-            cls.app.logger.info(f"Cannot find language {language}. Default to en.")
+            cls.app.logger.info("Unknown language, default to en", language=language)
             language = "en"
 
         g.language = language
@@ -68,7 +68,9 @@ class TranslationHandler:
             return string.format(**interpolation)
 
         if string not in cls.translations[language]:
-            cls.app.logger.warning(f'Unknown translation to {language} for "{string}"')
+            cls.app.logger.warning(
+                "Unknown translation", language=language, string=string
+            )
             return string.format(**interpolation)
 
         return cls.translations[language][string].format(**interpolation)