From 4884db8fb6c0a29ce41057adb2416c1b0f79cbfb Mon Sep 17 00:00:00 2001 From: AJ Slater Date: Sun, 10 May 2026 16:32:03 -0700 Subject: [PATCH] Downgrade routine anon-403s on /api/v3/auth/profile/ to DEBUG MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A fresh browser visit to Codex probes /api/v3/auth/profile/ before any session cookie exists, which Django's BaseHandler.get_response logs as a WARNING ("Forbidden: /api/v3/auth/profile/") for every first-time visitor. That drowns the main log in routine noise. Add a logging.Filter on django.request that downgrades records matching that exact "Forbidden: " pattern to DEBUG, parameterized by a small frozenset of known-noisy paths so abuse on other endpoints still surfaces at WARNING. Also move django.request into the loggers dict where dictConfig will actually see it — the old top-level placement was silently ignored. Records still flow to the root loguru handler via propagation. Co-Authored-By: Claude Opus 4.7 (1M context) --- codex/settings/logging.py | 57 +++++++++++++++++++++--------- tests/test_logging_filter.py | 68 ++++++++++++++++++++++++++++++++++++ 2 files changed, 108 insertions(+), 17 deletions(-) create mode 100644 tests/test_logging_filter.py 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