diff --git a/codex/settings/logging.py b/codex/settings/logging.py index de3c5af70..e09f0a94b 100644 --- a/codex/settings/logging.py +++ b/codex/settings/logging.py @@ -1,10 +1,35 @@ """Logging Settings.""" -from logging import Handler -from typing import override +import logging +from logging import Filter, Handler +from typing import Final, override from loguru import logger +# Paths whose routine anon-403s are noise, not abuse. The first-load +# probe to ``/api/v3/auth/profile/`` is the obvious offender — a fresh +# browser hits it before any session cookie exists. Django's +# BaseHandler.get_response logs every 4xx at WARNING; we downgrade the +# ones we expect so the main log stays useful. +_NOISY_FORBIDDEN_PATHS: Final[frozenset[str]] = frozenset({"/api/v3/auth/profile/"}) + + +class DowngradeNoisyForbiddenFilter(Filter): + """Downgrade routine anon 403s on known-noisy paths to DEBUG.""" + + @override + def filter(self, record) -> bool: + if record.levelno != logging.WARNING: + return True + msg = record.getMessage() + if not msg.startswith("Forbidden: "): + return True + path = msg.split(": ", 1)[1] + if path in _NOISY_FORBIDDEN_PATHS: + record.levelno = logging.DEBUG + record.levelname = "DEBUG" + return True + class LoguruHandler(Handler): """Redirect logging to loguru.""" @@ -71,9 +96,22 @@ def get_logging_settings(loglevel: str | int, *, debug: bool) -> dict[str, int | } ) level = "DEBUG" if loglevel == "TRACE" else loglevel + # ``django.request`` belongs inside ``loggers`` so dictConfig sees it; + # putting it at the top level (as this file used to) is silently + # ignored. Records still reach the root ``loguru`` handler via + # propagation, but the filter only runs when the logger is declared + # here. + loggers["django.request"] = { + "filters": ["downgrade_noisy_forbidden"], + } return { "version": 1, "disable_existing_loggers": True, + "filters": { + "downgrade_noisy_forbidden": { + "()": "codex.settings.logging.DowngradeNoisyForbiddenFilter", + }, + }, "handlers": { "loguru": { "class": "codex.settings.logging.LoguruHandler", @@ -84,20 +122,5 @@ def get_logging_settings(loglevel: str | int, *, debug: bool) -> dict[str, int | "level": level, "propagate": True, }, - "django": { - "handlers": ["loguru"], - "level": level, - "propagate": True, - }, - "django.request": { - "handlers": ["loguru"], - "level": level, - "propagate": True, - }, - "django.server": { - "handlers": ["loguru"], - "level": level, - "propagate": True, - }, "loggers": loggers, } diff --git a/tests/test_logging_filter.py b/tests/test_logging_filter.py new file mode 100644 index 000000000..c265c7428 --- /dev/null +++ b/tests/test_logging_filter.py @@ -0,0 +1,68 @@ +"""Tests for the noisy-Forbidden log filter.""" + +import logging +from typing import Final, override + +from django.test import TestCase + +from codex.settings.logging import DowngradeNoisyForbiddenFilter + +_FILTER_NAME: Final = "test" + + +def _build_record(level: int, msg: str, *args: object) -> logging.LogRecord: + return logging.LogRecord( + name="django.request", + level=level, + pathname=__file__, + lineno=0, + msg=msg, + args=args, + exc_info=None, + ) + + +class DowngradeNoisyForbiddenFilterTests(TestCase): + """Cover the level-downgrade logic on the request logger filter.""" + + @override + def setUp(self) -> None: + """Build one filter shared across the cases.""" + self.flt = DowngradeNoisyForbiddenFilter(_FILTER_NAME) # pyright: ignore[reportUninitializedInstanceVariable] + + def test_downgrades_noisy_path(self) -> None: + """First-load profile probe becomes DEBUG.""" + record = _build_record( + logging.WARNING, "%s: %s", "Forbidden", "/api/v3/auth/profile/" + ) + kept = self.flt.filter(record) + assert kept is True + assert record.levelno == logging.DEBUG + assert record.levelname == "DEBUG" + + def test_keeps_unrelated_forbidden_at_warning(self) -> None: + """A Forbidden on a non-noisy path stays at WARNING.""" + record = _build_record( + logging.WARNING, "%s: %s", "Forbidden", "/api/v3/admin/users/" + ) + kept = self.flt.filter(record) + assert kept is True + assert record.levelno == logging.WARNING + + def test_keeps_non_forbidden_at_warning(self) -> None: + """A Bad Request line through django.request stays at WARNING.""" + record = _build_record( + logging.WARNING, "%s: %s", "Bad Request", "/api/v3/auth/profile/" + ) + kept = self.flt.filter(record) + assert kept is True + assert record.levelno == logging.WARNING + + def test_ignores_non_warning_levels(self) -> None: + """ERROR-level records pass through untouched.""" + record = _build_record( + logging.ERROR, "%s: %s", "Forbidden", "/api/v3/auth/profile/" + ) + kept = self.flt.filter(record) + assert kept is True + assert record.levelno == logging.ERROR