From 105fd42d2206430d1819ec7b223bf5f4a99250c4 Mon Sep 17 00:00:00 2001 From: Finn Stutzenstein Date: Thu, 22 Oct 2026 18:37:12 +0000 Subject: [PATCH] Log every request once and keep the language per request Request logging: - One line per request from Flask hooks instead of the LoggingMiddleware. It now also covers static files, unknown URLs, 500 errors and the responses of the CSRF and auth middlewares. In debug mode, where Flask skips after_request on exceptions, the status is logged as 500. - All fields are logged as key=value. - The session is logged as a short SHA-256 prefix instead of the raw id. - In debug mode, the request lines of the Werkzeug dev server are filtered out, since the app logs requests itself. Translations: - TranslationHandler keeps the language in flask.g instead of a class attribute, so concurrent requests cannot overwrite each other's language. - Translating or rendering a template without a language raises LanguageNotSet. Requests that do not pass the I18NMiddleware are logged with lang=None. Co-Authored-By: Claude Opus 5.5 --- max/app.py | 11 +++------ max/exceptions.py | 7 ++++++ max/log.py | 55 +++++++++++++++++++++++++++++++++++++++++++++ max/middlewares.py | 36 +---------------------------- max/sessions.py | 7 ++++++ max/translations.py | 35 +++++++++++++++++++++-------- 6 files changed, 99 insertions(+), 52 deletions(-) diff --git a/max/app.py b/max/app.py index 49588ba..8264488 100644 --- a/max/app.py +++ b/max/app.py @@ -8,13 +8,8 @@ from .auth import AuthMiddleware, init as init_auth from .cli import register_cli from .csrf import CsrfMiddleware from .db import database -from .log import init_logging -from .middlewares import ( - ExceptionMiddleware, - I18NMiddleware, - LoggingMiddleware, - add_middleware_stack, -) +from .log import init_logging, init_request_logging +from .middlewares import ExceptionMiddleware, I18NMiddleware, add_middleware_stack from .routes import init_routes from .security_headers import init_security_headers from .sessions import SessionInterface @@ -63,9 +58,9 @@ def main(): CsrfMiddleware, AuthMiddleware, I18NMiddleware, - LoggingMiddleware, ExceptionMiddleware, ) + init_request_logging(app) database.init(app) app.session_interface = SessionInterface() register_cli(app) diff --git a/max/exceptions.py b/max/exceptions.py index 80a9564..cf94b62 100644 --- a/max/exceptions.py +++ b/max/exceptions.py @@ -19,3 +19,10 @@ class PermissionDenied(MaxException): Deliberately answered with a 404, like NotFound, so nobody can tell whether the object exists. """ + + +class LanguageNotSet(MaxException): + """ + Something is translated outside of the I18NMiddleware, which sets the + language of the request. + """ diff --git a/max/log.py b/max/log.py index ee1fc37..6e58a10 100644 --- a/max/log.py +++ b/max/log.py @@ -1,7 +1,21 @@ import logging import sys +import time from logging.config import dictConfig +from flask import g, request, session + +from max.db import database +from max.middlewares import get_real_remote_addr +from max.translations import TranslationHandler + + +class NoDevServerRequestsFilter(logging.Filter): + """Drops the request lines of the Werkzeug dev server, the app logs requests itself""" + + def filter(self, record): + return not (isinstance(record.msg, str) and record.msg.endswith('"%s" %s %s')) + def init_logging(app): dictConfig( @@ -22,3 +36,44 @@ def init_logging(app): ) logger = logging.getLogger(app.name) logger.setLevel(logging.DEBUG if app.debug else logging.INFO) + if app.debug: + logging.getLogger("werkzeug").addFilter(NoDevServerRequestsFilter()) + + +def init_request_logging(app): + """Logs one line per request, including static files, unknown URLs and errors""" + + @app.before_request + def start_request_logging(): + g.request_start = time.time() + request.real_remote_addr = get_real_remote_addr(app) + + @app.after_request + def remember_response(response): + g.response = response + return response + + @app.teardown_request + def log_request(exception): + # In debug mode, Flask skips after_request for unhandled exceptions, + # so the response may be None + response = g.get("response") + start = g.get("request_start") + time_in_ms = f"{(time.time() - start) * 1000:.2f}" if start else None + + app.logger.info( + 'method=%s url=%s ip=%s user_agent="%s" referrer="%s" db_queries=%s ' + + "status=%s content_length=%s user_id=%s session=%s lang=%s time_ms=%s", + request.method, + request.url, + get_real_remote_addr(app), + request.user_agent, + request.referrer, + database.collect_query_count(), + response.status_code if response is not None else 500, + response.content_length if response is not None else None, + session.get("user_id"), + session.get_log_id(), + TranslationHandler.get_language(), + time_in_ms, + ) diff --git a/max/middlewares.py b/max/middlewares.py index 6bc21ec..630b75b 100644 --- a/max/middlewares.py +++ b/max/middlewares.py @@ -1,8 +1,5 @@ -import time +from flask import request, session -from flask import Response, request, session - -from max.db import database from max.exceptions import NotFound, PermissionDenied from max.not_found_view import NotFoundView from max.translations import TranslationHandler @@ -27,37 +24,6 @@ def get_real_remote_addr(app): return real_ip -class LoggingMiddleware(BaseMiddleware): - def __call__(self, *args, **kwargs): - setattr(request, "real_remote_addr", get_real_remote_addr(self.app)) - - start = time.time() - - result = self.handler(*args, **kwargs) - response: Response = self.app.make_response(result) - - end = time.time() - time_in_ms = f"{(end-start)*1000:.2f}" - - self.app.logger.info( - '%s %s %s user_agent="%s" referrer="%s" db_queries=%s %s ' - + "%s user_id=%s session=%s lang=%s %sms", - request.method, - request.url, - request.real_remote_addr, - request.user_agent, - request.referrer, - database.collect_query_count(), - response.status_code, - response.content_length, - session.get("user_id"), - session.id, - TranslationHandler.language, - time_in_ms, - ) - return result - - class ExceptionMiddleware(BaseMiddleware): def __call__(self, *args, **kwargs): try: diff --git a/max/sessions.py b/max/sessions.py index 166172f..c1f0ab9 100644 --- a/max/sessions.py +++ b/max/sessions.py @@ -1,3 +1,4 @@ +import hashlib import time from flask import request @@ -91,6 +92,12 @@ class Session(CallbackDict, SessionMixin): def set_new_id(self): self.id = get_random_string(32) + def get_log_id(self): + """Identifies the session in the logs without revealing the id""" + if not self.id: + return None + return hashlib.sha256(self.id.encode("utf-8")).hexdigest()[:12] + def regenerate(self): """Keeps the data under a new id. The old id becomes invalid.""" del session_storage[self.id] diff --git a/max/translations.py b/max/translations.py index 64adcdf..c20baba 100644 --- a/max/translations.py +++ b/max/translations.py @@ -2,6 +2,10 @@ import json import os import re +from flask import g, has_request_context + +from max.exceptions import LanguageNotSet + ACCEPT_LANGUAGE_HEADER_REGEX = re.compile(r"([a-zA-Z]{2,3})(-[a-zA-Z\-]+)?") @@ -11,7 +15,6 @@ def t(*args, **kwargs): class TranslationHandler: translations = {} - language = "en" language_available = {"en": True} always_reload_translations = False @@ -19,7 +22,7 @@ class TranslationHandler: def init(cls, app): cls.app = app cls.always_reload_translations = app.debug - app.context_processor(lambda: dict(t=t, language=cls.language)) + app.context_processor(lambda: dict(t=t, language=cls.get_assured_language())) @classmethod def is_language_available(cls, language): @@ -29,13 +32,28 @@ class TranslationHandler: ) return cls.language_available[language] + @classmethod + def get_language(cls): + """The language of the current request, None if it was not set""" + if not has_request_context(): + return None + return g.get("language") + + @classmethod + def get_assured_language(cls): + """The language of the current request, which must be set""" + language = cls.get_language() + if language is None: + raise LanguageNotSet() + return language + @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.") language = "en" - cls.language = language + g.language = language if language != "en" and ( cls.always_reload_translations or language not in cls.translations ): @@ -45,16 +63,15 @@ class TranslationHandler: @classmethod def translate(cls, string, **interpolation): - if cls.language == "en": + language = cls.get_assured_language() + if language == "en": return string.format(**interpolation) - if string not in cls.translations[cls.language]: - cls.app.logger.warning( - f'Unknown translation to {cls.language} for "{string}"' - ) + if string not in cls.translations[language]: + cls.app.logger.warning(f'Unknown translation to {language} for "{string}"') return string.format(**interpolation) - return cls.translations[cls.language][string].format(**interpolation) + return cls.translations[language][string].format(**interpolation) @classmethod def parse_language_header(cls, header):