From 50e55c912e53d9f0784e0ffc1dc2fcbb724aa6c2 Mon Sep 17 00:00:00 2001 From: Jon Froehlich Date: Tue, 28 Jul 2026 17:45:49 -0700 Subject: [PATCH 1/2] Make debug.log rotation multiprocess-safe via concurrent-log-handler (#1439) Gunicorn runs 3 workers on -test and prod, each opening the same media/debug.log through LOGGING['handlers']['file']. The stdlib RotatingFileHandler is not multiprocess-safe: when one worker rotated, the others kept writing to the renamed inode and then rotated the nearly-empty new file themselves, so backups truncated far below maxBytes and log records were silently lost (see #1439 for the prod evidence). Swap the handler class for concurrent_log_handler. ConcurrentRotatingFileHandler (new pinned dependency), which takes a cross-process file lock around every write and rollover. Its lock file is redirected to /tmp rather than its default location next to the log, because LOG_FILE lives inside the web-served media root; /tmp is shared by all workers since they run in one container. The #1283 NullHandler degrade path is unchanged. Tests pin the new handler class, assert the lock dir stays out of MEDIA_ROOT, and build the real handler via dictConfig to guard the class path and kwargs (a typo'd kwarg would crash django.setup() on every server). Co-Authored-By: Claude Fable 5 --- CLAUDE.md | 2 +- makeabilitylab/settings.py | 26 +++++++++-- makeabilitylab/settings_test.py | 2 +- requirements.txt | 8 ++++ website/tests/test_logging_config.py | 70 ++++++++++++++++++++++++++-- 5 files changed, 98 insertions(+), 10 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 6c68ed95..de033d56 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -130,7 +130,7 @@ the existing viewset/serializer pattern and keep `v1` fields additive-only - **Prod/test `config.ini` has only a `[Django]` section — no `[Postgres]` section.** Per `settings.py`, a missing `[Postgres]` section means Django uses the fallback `DATABASES` default (`HOST='db'`) — i.e. the dockerized `db` service of the active compose file. A `[Postgres]` section, if added, would override it. So the DB is the in-stack `db` container in **every** environment (no external Postgres); on the servers that's the `db` service in `docker-compose.yml`. - `DEBUG` resolution order: `DJANGO_ENV=PROD` forces False → `config.ini [Django] DEBUG` → `DJANGO_ENV=DEBUG` forces True → default False. - `TIME_ZONE = 'America/Los_Angeles'`. `ML_WEBSITE_VERSION` in settings is shown in the admin header and used in release tagging. -- **Logging (#1283):** `debug.log` lives at `LOG_DIR/debug.log`, where `LOG_DIR` is `$ML_LOG_DIR` or `/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — the web-served `/logs/debug.log` depends on that. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. If the dir isn't writable the file handler degrades to a `NullHandler` rather than crashing `django.setup()`, and since there's no console on the servers that state surfaces via `/version.json` (`log_to_file`) and a superuser-only callout on the admin dashboard. +- **Logging (#1283):** `debug.log` lives at `LOG_DIR/debug.log`, where `LOG_DIR` is `$ML_LOG_DIR` or `/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — the web-served `/logs/debug.log` depends on that. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. If the dir isn't writable the file handler degrades to a `NullHandler` rather than crashing `django.setup()`, and since there's no console on the servers that state surfaces via `/version.json` (`log_to_file`) and a superuser-only callout on the admin dashboard. Rotation uses `concurrent-log-handler` (#1439) because Gunicorn's 3 workers share one file — the stdlib `RotatingFileHandler` races on rollover across processes; its lock file is kept in `/tmp`, not the web-served media root. ### Container startup side effects (`docker-entrypoint.sh`) diff --git a/makeabilitylab/settings.py b/makeabilitylab/settings.py index 1e6b4e52..16a90d00 100644 --- a/makeabilitylab/settings.py +++ b/makeabilitylab/settings.py @@ -13,7 +13,8 @@ """ import os -from configparser import ConfigParser +import tempfile # for the log-rotation lock-file dir, see _file_log_handler +from configparser import ConfigParser import datetime # for DATE_MAKEABILITYLAB_FORMED global # Build paths inside the project like this: os.path.join(BASE_DIR, ...) @@ -86,8 +87,8 @@ SECURE_PROXY_SSL_HEADER = ('HTTP_X_FORWARDED_PROTO', 'https') # Makeability Lab Global Variables, including Makeability Lab version -ML_WEBSITE_VERSION = "2.31.1" # Keep this updated with each release and also change the short description below -ML_WEBSITE_VERSION_DESCRIPTION = "The Django log path is now derived from the project root instead of a hardcoded container path, and an unwritable log directory degrades gracefully instead of killing startup (#1283). Because the servers have no console, /version.json now reports whether file logging is actually live." +ML_WEBSITE_VERSION = "2.31.2" # Keep this updated with each release and also change the short description below +ML_WEBSITE_VERSION_DESCRIPTION = "debug.log rotation is now multiprocess-safe (concurrent-log-handler): Gunicorn's three workers previously raced on rollover and silently lost log records (#1439)." DATE_MAKEABILITYLAB_FORMED = datetime.date(2012, 1, 1) # Date Makeability Lab was formed MAX_BANNERS = 7 # Maximum number of banners on a page @@ -135,7 +136,7 @@ def _ensure_log_dir_writable(log_dir): 1. This checks the *directory*, not the eventual log file. A dir that is writable but already holds a root-owned, read-only ``debug.log`` would - still let RotatingFileHandler raise on open. That doesn't match the real + still let the file handler raise on open. That doesn't match the real deploy model, where media/ is owned by the app's own user. 2. ``os.access(dir, os.W_OK)`` returns True for root regardless of the directory mode, so a mode-555 dir wouldn't be caught when running as root. @@ -158,6 +159,14 @@ def _file_log_handler(log_file, level, enabled): NullHandler instead, which keeps every logger's ``'file'`` handler reference valid while never touching disk — so startup degrades instead of dying. + The handler class is ``ConcurrentRotatingFileHandler`` (issue #1439), not + the stdlib ``RotatingFileHandler``: on -test and prod, Gunicorn runs 3 + worker processes (docker-entrypoint.sh) that each open the *same* log file, + and the stdlib handler is not multiprocess-safe — workers raced on rollover, + renaming each other's freshly created files and silently dropping records. + The concurrent handler takes a cross-process file lock around every write + and rollover, so one file shared by all workers stays correct. + Split out of the ``LOGGING`` literal so both branches are directly testable; ``LOGGING`` is evaluated once at import, so a test can't re-derive it. See ``website/tests/test_logging_config.py``. @@ -166,10 +175,17 @@ def _file_log_handler(log_file, level, enabled): return {'class': 'logging.NullHandler'} return { 'level': level, - 'class': 'logging.handlers.RotatingFileHandler', + 'class': 'concurrent_log_handler.ConcurrentRotatingFileHandler', 'filename': log_file, 'maxBytes': 1024*1024*5, # 5 MB 'backupCount': 6, + # By default the handler puts its lock file next to the log — i.e. + # inside the web-served media root (LOG_FILE lives there so the file is + # reachable over SSH/the web; see the LOG_DIR note below). Keep lock + # files out of the public tree. /tmp is container-local, which is fine: + # all Gunicorn workers share one container, so they see the same lock. + # test_lock_file_stays_out_of_media_root pins this. + 'lock_file_directory': tempfile.gettempdir(), 'formatter': 'verbose', # can switch between verbose and simple } diff --git a/makeabilitylab/settings_test.py b/makeabilitylab/settings_test.py index 6387fee9..adf63722 100644 --- a/makeabilitylab/settings_test.py +++ b/makeabilitylab/settings_test.py @@ -34,7 +34,7 @@ "DATABASE_PORT", DATABASES["default"].get("PORT", "5432") # noqa: F405 ) -# The base settings wire a RotatingFileHandler to /code/media/debug.log (a +# The base settings wire a rotating file handler to /code/media/debug.log (a # container path). Django evaluates LOGGING at startup, so on any host without # that directory — a CI runner, a fresh checkout — django.setup() crashes # before a single test runs. Swap just the 'file' handler for a no-op; this diff --git a/requirements.txt b/requirements.txt index 54c90b69..83e41be9 100644 --- a/requirements.txt +++ b/requirements.txt @@ -133,6 +133,14 @@ django-prose-editor[sanitize]==0.26.0 # See: https://docs.djangoproject.com/en/5.2/howto/deployment/wsgi/gunicorn/ gunicorn==23.0.0 +# concurrent-log-handler - multiprocess-safe rotating file log handler, used by +# LOGGING['handlers']['file'] in settings.py. Gunicorn's 3 workers each open the +# same media/debug.log, and the stdlib RotatingFileHandler is not +# multiprocess-safe: workers raced on rollover and silently lost log records +# (issue #1439). This handler takes a cross-process file lock (via its +# portalocker dependency) around every write and rollover. +concurrent-log-handler==0.9.29 + # ----------------------------------------------------------------------------- # Security & Networking # ----------------------------------------------------------------------------- diff --git a/website/tests/test_logging_config.py b/website/tests/test_logging_config.py index 59910e70..049b0687 100644 --- a/website/tests/test_logging_config.py +++ b/website/tests/test_logging_config.py @@ -23,6 +23,8 @@ Mostly pure logic; the admin-dashboard tests need the DB for a superuser login. """ +import logging +import logging.config import os import shutil import tempfile @@ -70,15 +72,77 @@ def test_uncreatable_dir_returns_false(self): class FileLogHandlerTests(SimpleTestCase): - """Both branches of the builder behind ``LOGGING['handlers']['file']``.""" + """Both branches of the builder behind ``LOGGING['handlers']['file']``. - def test_enabled_builds_rotating_file_handler(self): + The enabled branch must build a *multiprocess-safe* rotating handler + (issue #1439): Gunicorn's 3 workers share one debug.log, and the stdlib + ``RotatingFileHandler`` races on rollover across processes — workers rename + each other's freshly rotated files and records are silently lost. + """ + + def test_enabled_builds_concurrent_rotating_file_handler(self): handler = _file_log_handler("/tmp/probe/debug.log", "INFO", True) - self.assertEqual(handler["class"], "logging.handlers.RotatingFileHandler") + self.assertEqual( + handler["class"], "concurrent_log_handler.ConcurrentRotatingFileHandler" + ) self.assertEqual(handler["filename"], "/tmp/probe/debug.log") self.assertEqual(handler["level"], "INFO") self.assertEqual(handler["formatter"], "verbose") + def test_lock_file_stays_out_of_media_root(self): + """The handler's lock file must not land in the web-served media tree. + + By default concurrent-log-handler drops its lock file next to the log, + and LOG_FILE lives inside MEDIA_ROOT (everything under it is publicly + downloadable). The config must redirect lock files elsewhere. + """ + handler = _file_log_handler(settings.LOG_FILE, "INFO", True) + lock_dir = handler["lock_file_directory"] + media_root = os.path.join(os.path.normpath(settings.MEDIA_ROOT), "") + self.assertFalse( + os.path.normpath(lock_dir).startswith(media_root) + or os.path.normpath(lock_dir) == os.path.normpath(settings.MEDIA_ROOT), + f"lock_file_directory {lock_dir!r} is inside MEDIA_ROOT", + ) + + def test_enabled_handler_config_is_instantiable(self): + """``dictConfig`` must be able to build and use the real handler. + + Guards the class path and constructor kwargs against package changes + (e.g. ``lock_file_directory`` is a concurrent-log-handler extension — + a typo'd kwarg here would crash ``django.setup()`` on every server). + Writes one record and checks it landed, and that no lock file was + dropped next to the log. + """ + tmp = tempfile.mkdtemp() + log_file = os.path.join(tmp, "debug.log") + logger_name = "probe1439" + try: + handler_cfg = _file_log_handler(log_file, "INFO", True) + # 'formatter' refers to LOGGING['formatters'] by name; this minimal + # config has none, so drop it (dictConfig would fail the lookup). + handler_cfg.pop("formatter") + logging.config.dictConfig({ + "version": 1, + "disable_existing_loggers": False, + "handlers": {"probe1439_file": handler_cfg}, + "loggers": { + logger_name: {"handlers": ["probe1439_file"], "level": "INFO"}, + }, + }) + logging.getLogger(logger_name).info("probe record") + with open(log_file) as f: + self.assertIn("probe record", f.read()) + self.assertEqual(os.listdir(tmp), ["debug.log"]) + finally: + # Detach and close the handler so the temp dir can be removed and + # no stray handler outlives this test in global logging state. + probe_logger = logging.getLogger(logger_name) + for h in list(probe_logger.handlers): + probe_logger.removeHandler(h) + h.close() + shutil.rmtree(tmp, ignore_errors=True) + def test_disabled_degrades_to_nullhandler(self): handler = _file_log_handler("/tmp/probe/debug.log", "INFO", False) self.assertEqual(handler, {"class": "logging.NullHandler"}) From 6d2894aa4c04ab419b84660527dd3bd254723cae Mon Sep 17 00:00:00 2001 From: Jon Froehlich Date: Wed, 29 Jul 2026 08:20:36 -0700 Subject: [PATCH 2/2] Address code-review findings on the #1439 rotation fix Five follow-ups from the review of PR #1442, all in the same area: 1. The handler class was a hard dependency: dictConfig raises ValueError on an unimportable class, aborting django.setup() with none of the #1283 degrade signals. That state is reachable without a broken deploy -- the container bind-mounts the checkout over /code while site-packages come from the last image build, so a branch switch (or the gap between the deploy webhook's git pull and its build) can run this settings.py against an older image. Probe the import once and fall back to the stdlib RotatingFileHandler: racy on rollover, but logging keeps working. 2. Nothing validated the lock directory. gettempdir() itself can raise, and a lock file that can't be opened fails inside emit() -> handleError (stderr, unread on the servers) while /version.json still says healthy. Resolve and writability-check the dir up front; degrade if unusable. 3. The lock path was a fixed name in a world-writable sticky dir (/tmp/.__debug.lock, opened "r+"). A root-created one -- the devcontainer connects as root -- locks the apache workers out permanently, since /tmp's sticky bit stops them unlinking it. Namespace the dir by uid, so a lock is only ever shared with same-uid processes (the deployed case). 4. The instantiation test's dictConfig closed every handler Django had configured, for the rest of the test process. Re-apply settings.LOGGING. 5. django.db.backends emitted a record per SQL query on -test (DEBUG=True) -- the bulk of the volume behind the rapid rollovers, now also the biggest payer of the per-record cross-process lock, and raw SQL in a publicly downloadable file. Pinned to INFO. Degrading quietly is the thing #1283 exists to prevent, so the resulting handler is reported as log_rotation on /version.json (derived from the built LOGGING dict so it can't drift) and printed as a startup warning. Co-Authored-By: Claude Opus 5 (1M context) --- CLAUDE.md | 2 +- makeabilitylab/settings.py | 124 ++++++++++++++++++++----- makeabilitylab/settings_test.py | 3 + website/tests/test_logging_config.py | 80 +++++++++++++++- website/tests/test_version_endpoint.py | 11 +++ website/views/version.py | 13 ++- 6 files changed, 208 insertions(+), 25 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index de033d56..ecc8c344 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -130,7 +130,7 @@ the existing viewset/serializer pattern and keep `v1` fields additive-only - **Prod/test `config.ini` has only a `[Django]` section — no `[Postgres]` section.** Per `settings.py`, a missing `[Postgres]` section means Django uses the fallback `DATABASES` default (`HOST='db'`) — i.e. the dockerized `db` service of the active compose file. A `[Postgres]` section, if added, would override it. So the DB is the in-stack `db` container in **every** environment (no external Postgres); on the servers that's the `db` service in `docker-compose.yml`. - `DEBUG` resolution order: `DJANGO_ENV=PROD` forces False → `config.ini [Django] DEBUG` → `DJANGO_ENV=DEBUG` forces True → default False. - `TIME_ZONE = 'America/Los_Angeles'`. `ML_WEBSITE_VERSION` in settings is shown in the admin header and used in release tagging. -- **Logging (#1283):** `debug.log` lives at `LOG_DIR/debug.log`, where `LOG_DIR` is `$ML_LOG_DIR` or `/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — the web-served `/logs/debug.log` depends on that. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. If the dir isn't writable the file handler degrades to a `NullHandler` rather than crashing `django.setup()`, and since there's no console on the servers that state surfaces via `/version.json` (`log_to_file`) and a superuser-only callout on the admin dashboard. Rotation uses `concurrent-log-handler` (#1439) because Gunicorn's 3 workers share one file — the stdlib `RotatingFileHandler` races on rollover across processes; its lock file is kept in `/tmp`, not the web-served media root. +- **Logging (#1283):** `debug.log` lives at `LOG_DIR/debug.log`, where `LOG_DIR` is `$ML_LOG_DIR` or `/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — the web-served `/logs/debug.log` depends on that. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. If the dir isn't writable the file handler degrades to a `NullHandler` rather than crashing `django.setup()`, and since there's no console on the servers that state surfaces via `/version.json` (`log_to_file`) and a superuser-only callout on the admin dashboard. Rotation uses `concurrent-log-handler` (#1439) because Gunicorn's 3 workers share one file — the stdlib `RotatingFileHandler` races on rollover across processes. Its lock file goes in a per-uid temp dir (`/tmp/makelab-log-locks-`), never the web-served media root and never shared across users. If the package isn't importable (the bind-mounted checkout can be ahead of the image's site-packages) or no lock dir is usable, the handler degrades to the stdlib `RotatingFileHandler` instead of crashing `django.setup()`; `/version.json` reports which one is live as `log_rotation`. `django.db.backends` is pinned to INFO so per-query SQL doesn't dominate the log (or the lock). ### Container startup side effects (`docker-entrypoint.sh`) diff --git a/makeabilitylab/settings.py b/makeabilitylab/settings.py index 16a90d00..a0ee9298 100644 --- a/makeabilitylab/settings.py +++ b/makeabilitylab/settings.py @@ -123,6 +123,21 @@ # degraded state is surfaced two web-reachable ways instead: the 'log_to_file' field # on /version.json (website/views/version.py) and a warning callout on the admin # dashboard (website/templates/admin/index.html). +# Probed once, at import, so a missing package degrades the handler instead of +# killing startup (see _file_log_handler). This matters because the container +# bind-mounts the repo over /code while site-packages come from whenever the +# image was last built: a branch switch or the window between the deploy +# webhook's `git pull` and `docker compose build` can leave new settings.py +# running against an older image. dictConfig raises ValueError ("Unable to +# configure handler 'file'") on an unimportable class, and that aborts +# django.setup() — no NullHandler degrade, no /version.json, no admin callout. +try: + import concurrent_log_handler # noqa: F401 (imported only to probe availability) + _HAS_CONCURRENT_LOG_HANDLER = True +except ImportError: + _HAS_CONCURRENT_LOG_HANDLER = False + + def _ensure_log_dir_writable(log_dir): """Create ``log_dir`` if needed and return True if it looks writable. @@ -152,42 +167,82 @@ def _ensure_log_dir_writable(log_dir): return False -def _file_log_handler(log_file, level, enabled): - """Return the ``LOGGING['handlers']['file']`` config dict. +def _lock_file_directory(): + """Return a writable directory for the rotation lock file, or None. + + ``ConcurrentRotatingFileHandler`` coordinates processes through a lock file. + Two things about *where* that file goes matter here: + + 1. By default it lands next to the log — i.e. inside the web-served media + root (LOG_FILE lives there so the file is reachable over SSH/the web; + see the LOG_DIR note below). Lock files must not be in the public tree. + ``test_lock_file_stays_out_of_media_root`` pins this. + 2. The lock name is derived from the log's basename alone, so every process + sharing one temp dir shares ``/tmp/.__debug.lock`` — and that file is + opened ``"r+"``. If a root process creates it first (the devcontainer + connects as root; see CLAUDE.md), the ``apache`` workers get a + PermissionError on every write and, thanks to /tmp's sticky bit, can't + even unlink it to recover — file logging would die silently. So the + directory is namespaced by uid: processes only ever share a lock with + same-uid processes, which is exactly the case that needs the locking + (all Gunicorn workers run as ``apache`` in one container). + + Returns None if the directory can't be created or written — including the + pathological case where ``gettempdir()`` itself finds nowhere usable and + raises. The caller then falls back to the stdlib handler, because the + concurrent handler surfaces lock failures through ``handleError`` (stderr, + which nothing reads on the servers) while ``/version.json`` would still + report healthy — the exact blind spot #1283 exists to close. + """ + try: + lock_dir = os.path.join(tempfile.gettempdir(), + f'makelab-log-locks-{os.getuid()}') + except (OSError, AttributeError): + # No usable temp dir, or no getuid() (non-POSIX host). + return None + return lock_dir if _ensure_log_dir_writable(lock_dir) else None - When ``enabled`` is False (the log dir isn't writable) this returns a - NullHandler instead, which keeps every logger's ``'file'`` handler reference - valid while never touching disk — so startup degrades instead of dying. - The handler class is ``ConcurrentRotatingFileHandler`` (issue #1439), not - the stdlib ``RotatingFileHandler``: on -test and prod, Gunicorn runs 3 - worker processes (docker-entrypoint.sh) that each open the *same* log file, - and the stdlib handler is not multiprocess-safe — workers raced on rollover, - renaming each other's freshly created files and silently dropping records. - The concurrent handler takes a cross-process file lock around every write - and rollover, so one file shared by all workers stays correct. +def _file_log_handler(log_file, level, enabled): + """Return the ``LOGGING['handlers']['file']`` config dict. - Split out of the ``LOGGING`` literal so both branches are directly testable; + Three outcomes, in descending order of goodness: + + * ``ConcurrentRotatingFileHandler`` (issue #1439) — the intended one. On + -test and prod, Gunicorn runs 3 worker processes (docker-entrypoint.sh) + that each open the *same* log file, and the stdlib ``RotatingFileHandler`` + is not multiprocess-safe: workers raced on rollover, renaming each other's + freshly created files and silently dropping records. The concurrent + handler takes a cross-process lock around every write and rollover. + * The stdlib ``RotatingFileHandler`` — if the package isn't importable or + no lock directory is usable. Racy on rollover (i.e. #1439 is back), but + logging keeps working, which beats aborting ``django.setup()``. + * ``NullHandler`` — ``enabled`` is False, meaning the log dir isn't + writable. Keeps every logger's ``'file'`` handler reference valid while + never touching disk (issue #1283). + + Only the first is multiprocess-safe, so which one we got is reported as + ``log_rotation`` on ``/version.json`` (there is no console on the servers). + + Split out of the ``LOGGING`` literal so the branches are directly testable; ``LOGGING`` is evaluated once at import, so a test can't re-derive it. See ``website/tests/test_logging_config.py``. """ if not enabled: return {'class': 'logging.NullHandler'} - return { + handler = { 'level': level, - 'class': 'concurrent_log_handler.ConcurrentRotatingFileHandler', + 'class': 'logging.handlers.RotatingFileHandler', 'filename': log_file, 'maxBytes': 1024*1024*5, # 5 MB 'backupCount': 6, - # By default the handler puts its lock file next to the log — i.e. - # inside the web-served media root (LOG_FILE lives there so the file is - # reachable over SSH/the web; see the LOG_DIR note below). Keep lock - # files out of the public tree. /tmp is container-local, which is fine: - # all Gunicorn workers share one container, so they see the same lock. - # test_lock_file_stays_out_of_media_root pins this. - 'lock_file_directory': tempfile.gettempdir(), 'formatter': 'verbose', # can switch between verbose and simple } + lock_dir = _lock_file_directory() if _HAS_CONCURRENT_LOG_HANDLER else None + if lock_dir is not None: + handler['class'] = 'concurrent_log_handler.ConcurrentRotatingFileHandler' + handler['lock_file_directory'] = lock_dir + return handler # NOTE: this default must stay in sync with MEDIA_ROOT (defined further down as @@ -262,6 +317,16 @@ def _file_log_handler(log_file, level, enabled): 'django.utils.autoreload': { 'level': 'INFO', # Change to 'INFO' or 'WARNING' }, + # Django logs every SQL query here at DEBUG, but only when DEBUG is on. + # That is on for local dev *and* on -test, where it was the bulk of the + # log volume behind #1439's rapid rollovers — and every record now takes + # a cross-process lock, so the noisiest logger is also the one paying + # the most for it. It also puts raw SQL in a file that is publicly + # downloadable (see the LOG_DIR note). Pinned to INFO, which silences + # query logging; set it back to DEBUG locally if you need to see them. + 'django.db.backends': { + 'level': 'INFO', + }, # This logger captures information about incoming HTTP requests, including details # about the request method, URL, and any exceptions that occur during request # processing. It’s useful for getting a high-level overview of the requests @@ -284,6 +349,21 @@ def _file_log_handler(log_file, level, enabled): }, } +# Which rotation handler we actually ended up with — derived from the built +# config rather than tracked separately so the two can't drift. Uppercase on +# purpose: like LOG_TO_FILE, it's read through django.conf.settings, here by +# /version.json ('log_rotation'). Only 'ConcurrentRotatingFileHandler' is +# multiprocess-safe; 'RotatingFileHandler' means we degraded and #1439's +# rollover race is live again, which is otherwise invisible on the servers. +LOG_ROTATION = LOGGING['handlers']['file']['class'].rsplit('.', 1)[-1] + +if LOG_TO_FILE and LOG_ROTATION != 'ConcurrentRotatingFileHandler': + # Secondary signal only, same as the LOG_TO_FILE warning above: the channel + # that works remotely is /version.json ('log_rotation'). + print(f"WARNING: falling back to {LOG_ROTATION} — log rotation is NOT " + f"multiprocess-safe (concurrent-log-handler importable: " + f"{_HAS_CONCURRENT_LOG_HANDLER}). Check /version.json 'log_rotation'.") + # Application definition INSTALLED_APPS = [ 'website.apps.WebsiteConfig', diff --git a/makeabilitylab/settings_test.py b/makeabilitylab/settings_test.py index adf63722..9d5669de 100644 --- a/makeabilitylab/settings_test.py +++ b/makeabilitylab/settings_test.py @@ -40,6 +40,9 @@ # before a single test runs. Swap just the 'file' handler for a no-op; this # keeps every logger's handler reference valid while never touching disk. LOGGING["handlers"]["file"] = {"class": "logging.NullHandler"} # noqa: F405 +# Keep the derived setting honest — it names the handler class actually wired +# up, and /version.json reports it (#1439). +LOG_ROTATION = "NullHandler" # Speed up the auth tests (Data Health suite creates real superuser rows). PASSWORD_HASHERS = ["django.contrib.auth.hashers.MD5PasswordHasher"] diff --git a/website/tests/test_logging_config.py b/website/tests/test_logging_config.py index 049b0687..5d2523ee 100644 --- a/website/tests/test_logging_config.py +++ b/website/tests/test_logging_config.py @@ -28,12 +28,17 @@ import os import shutil import tempfile +from unittest import mock from django.conf import settings from django.contrib.auth import get_user_model from django.test import SimpleTestCase, override_settings -from makeabilitylab.settings import _ensure_log_dir_writable, _file_log_handler +from makeabilitylab.settings import ( + _ensure_log_dir_writable, + _file_log_handler, + _lock_file_directory, +) from website.tests.base import DatabaseTestCase @@ -89,6 +94,56 @@ def test_enabled_builds_concurrent_rotating_file_handler(self): self.assertEqual(handler["level"], "INFO") self.assertEqual(handler["formatter"], "verbose") + def test_missing_package_degrades_to_stdlib_rotating_handler(self): + """An unimportable handler class must not abort ``django.setup()``. + + ``dictConfig`` raises ValueError on a class it can't resolve, and that + propagates out of ``django.setup()`` — no NullHandler degrade, no + /version.json, no admin callout. The container runs the bind-mounted + checkout against whatever site-packages the image was last built with, + so "settings.py is ahead of the installed packages" is a real state + (branch switch without --build; the gap between the deploy webhook's + git pull and its image build). Degrade to the racy-but-working stdlib + handler instead. + """ + with mock.patch("makeabilitylab.settings._HAS_CONCURRENT_LOG_HANDLER", False): + handler = _file_log_handler("/tmp/probe/debug.log", "INFO", True) + self.assertEqual(handler["class"], "logging.handlers.RotatingFileHandler") + # The kwarg is a concurrent-log-handler extension; passing it to the + # stdlib handler would be a TypeError at dictConfig time. + self.assertNotIn("lock_file_directory", handler) + self.assertEqual(handler["maxBytes"], 1024 * 1024 * 5) + self.assertEqual(handler["backupCount"], 6) + + def test_unusable_lock_dir_degrades_to_stdlib_rotating_handler(self): + """No usable lock dir → degrade rather than fail silently at emit(). + + The concurrent handler reports lock failures through ``handleError`` + (stderr, which nothing reads on the servers) while ``log_to_file`` + would still say healthy — so decide up front, where we can report it. + """ + with mock.patch("makeabilitylab.settings._lock_file_directory", return_value=None): + handler = _file_log_handler("/tmp/probe/debug.log", "INFO", True) + self.assertEqual(handler["class"], "logging.handlers.RotatingFileHandler") + self.assertNotIn("lock_file_directory", handler) + + def test_lock_dir_is_namespaced_by_uid(self): + """Processes must not share a lock file across users. + + The lock name comes from the log's basename alone, so a bare temp dir + gives every process ``/tmp/.__debug.lock`` — opened ``"r+"``. A + root-owned one (the devcontainer connects as root) locks out the + ``apache`` workers permanently, since /tmp's sticky bit stops them + unlinking it. A per-uid directory keeps the lock shared exactly where + it must be (same-uid Gunicorn workers) and nowhere else. + """ + lock_dir = _lock_file_directory() + self.assertIsNotNone(lock_dir) + self.assertNotEqual( + os.path.normpath(lock_dir), os.path.normpath(tempfile.gettempdir()) + ) + self.assertTrue(os.path.basename(lock_dir).endswith(str(os.getuid()))) + def test_lock_file_stays_out_of_media_root(self): """The handler's lock file must not land in the web-served media tree. @@ -113,6 +168,12 @@ def test_enabled_handler_config_is_instantiable(self): a typo'd kwarg here would crash ``django.setup()`` on every server). Writes one record and checks it landed, and that no lock file was dropped next to the log. + + Note the ``dictConfig`` below is destructive: a non-incremental config + runs ``logging.config._clearExistingHandlers()``, which closes and + unregisters *every* handler Django set up, for the rest of the test + process. The ``finally`` block re-applies ``settings.LOGGING`` so this + test can't quietly break whichever test runs after it. """ tmp = tempfile.mkdtemp() log_file = os.path.join(tmp, "debug.log") @@ -141,6 +202,8 @@ def test_enabled_handler_config_is_instantiable(self): for h in list(probe_logger.handlers): probe_logger.removeHandler(h) h.close() + # Rebuild the handlers the probe config tore down (see docstring). + logging.config.dictConfig(settings.LOGGING) shutil.rmtree(tmp, ignore_errors=True) def test_disabled_degrades_to_nullhandler(self): @@ -167,6 +230,21 @@ def test_default_log_file_is_under_media_root(self): ) +class LogRotationSettingTests(SimpleTestCase): + """``LOG_ROTATION`` is what /version.json reports as ``log_rotation``. + + It's derived from the built ``LOGGING`` dict so the reported handler can't + drift from the configured one — including in ``settings_test``, which swaps + the file handler for a NullHandler and must keep the two in step. + """ + + def test_log_rotation_names_the_configured_handler_class(self): + self.assertEqual( + settings.LOG_ROTATION, + settings.LOGGING["handlers"]["file"]["class"].rsplit(".", 1)[-1], + ) + + class AdminLoggingWarningTests(DatabaseTestCase): """The admin dashboard callout that surfaces degraded logging (#1283). diff --git a/website/tests/test_version_endpoint.py b/website/tests/test_version_endpoint.py index b3b865f4..86682451 100644 --- a/website/tests/test_version_endpoint.py +++ b/website/tests/test_version_endpoint.py @@ -65,6 +65,9 @@ def test_payload_from_settings_and_no_store_header(self): # Logging health (#1283) -- always present so a deploy check can assert on it. self.assertIn("log_to_file", data) self.assertIn("log_file", data) + # Which rotation handler is live (#1439) -- the only remote way to see + # that the multiprocess-safe handler degraded. + self.assertIn("log_rotation", data) def test_server_reflects_wsgi_server_software(self): # The view reports request.META["SERVER_SOFTWARE"] verbatim; on the real @@ -88,6 +91,14 @@ def test_reports_degraded_logging(self): self.assertFalse(data["log_to_file"]) self.assertEqual(data["log_file"], "/nope/debug.log") + @override_settings(LOG_ROTATION="RotatingFileHandler") + def test_reports_degraded_rotation(self): + """Anything but ``ConcurrentRotatingFileHandler`` means Gunicorn's three + workers can race on rollover again (#1439) -- invisible otherwise, since + there's no console on -test or prod.""" + data = json.loads(self.client.get("/version/").content) + self.assertEqual(data["log_rotation"], "RotatingFileHandler") + def test_build_info_missing_falls_back_to_unknown(self): with override_settings(): # Point at a path that doesn't exist. diff --git a/website/views/version.py b/website/views/version.py index c8c75ee2..e756d43e 100644 --- a/website/views/version.py +++ b/website/views/version.py @@ -28,7 +28,8 @@ "built_at": "2026-06-21T18:30:00-07:00", "server": "gunicorn/23.0.0", "log_to_file": true, - "log_file": "/code/media/debug.log" + "log_file": "/code/media/debug.log", + "log_rotation": "ConcurrentRotatingFileHandler" } The ``server`` field is the WSGI server's self-reported ``SERVER_SOFTWARE`` @@ -43,6 +44,12 @@ false`` means the app is running blind, and ``log_file`` says which directory was at fault. Nothing new is disclosed -- the path is derivable from the public repo. +``log_rotation`` names the live rotation handler class (#1439). Gunicorn runs 3 +workers over one debug.log, so it must be ``ConcurrentRotatingFileHandler``; +anything else means the multiprocess-safe handler degraded (package missing from +the image, or no usable lock directory) and workers can clobber each other's +rotated files again. + Note that ``log_to_file: true`` only means the log *directory* was writable at startup. To confirm records are really landing, tail the file over SSH at ``/cse/web/research/makelab/www[-test]/debug.log`` (the ``/logs/`` URL described in @@ -111,6 +118,10 @@ def version(request, format=None): # the only remote way to notice, since we have no console on -test/prod. "log_to_file": settings.LOG_TO_FILE, "log_file": settings.LOG_FILE, + # Which rotation handler is live (#1439). Anything other than + # "ConcurrentRotatingFileHandler" means the multiprocess-safe handler + # degraded and Gunicorn's workers can race on rollover again. + "log_rotation": settings.LOG_ROTATION, } response = JsonResponse(payload) response["Cache-Control"] = "no-store"