From 4a159006aa405847556e1d8656f78d29f20b3f83 Mon Sep 17 00:00:00 2001 From: Finn Stutzenstein Date: Fri, 23 Oct 2026 13:58:44 +0000 Subject: [PATCH] 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 --- max/app.py | 2 +- max/audit.py | 6 ++-- max/auth/passwords.py | 2 +- max/csrf.py | 15 ++++----- max/db/connection.py | 2 +- max/log.py | 78 ++++++++++++++++++++++++++++++++----------- max/log_format.py | 12 ------- max/translations.py | 6 ++-- 8 files changed, 74 insertions(+), 49 deletions(-) delete mode 100644 max/log_format.py diff --git a/max/app.py b/max/app.py index 8264488..94be752 100644 --- a/max/app.py +++ b/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 diff --git a/max/audit.py b/max/audit.py index 6f69950..27740c4 100644 --- a/max/audit.py +++ b/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) diff --git a/max/auth/passwords.py b/max/auth/passwords.py index 611b2dd..1a7513d 100644 --- a/max/auth/passwords.py +++ b/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) diff --git a/max/csrf.py b/max/csrf.py index da132a3..b93fb5c 100644 --- a/max/csrf.py +++ b/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", - 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), - ), + "Blocked cross-origin request", + 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 diff --git a/max/db/connection.py b/max/db/connection.py index dedbd87..5ec5d6f 100644 --- a/max/db/connection.py +++ b/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): diff --git a/max/log.py b/max/log.py index d09f536..f1eb34f 100644 --- a/max/log.py +++ b/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,21 +107,17 @@ def init_request_logging(app): time_in_ms = round((time.time() - start) * 1000, 2) if start else None app.logger.info( - "%s", - format_log_fields( - method=request.method, - url=request.url, - ip=get_real_remote_addr(app), - user_agent=request.user_agent.string, - referrer=request.referrer, - db_queries=database.collect_query_count(), - status=response.status_code if response is not None else 500, - content_length=( - 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, - ), + "request", + method=request.method, + url=request.url, + ip=get_real_remote_addr(app), + user_agent=request.user_agent.string, + referrer=request.referrer, + db_queries=database.collect_query_count(), + status=response.status_code if response is not None else 500, + content_length=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, ) diff --git a/max/log_format.py b/max/log_format.py deleted file mode 100644 index 26fc653..0000000 --- a/max/log_format.py +++ /dev/null @@ -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() - ) diff --git a/max/translations.py b/max/translations.py index c20baba..4457c04 100644 --- a/max/translations.py +++ b/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)