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 <noreply@anthropic.com>

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)

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.
+    """

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,
+        )

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:

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]

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):