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