Merge pull request #1442 from makeabilitylab/1439-gunicorn-log-rotation-race

Make debug.log rotation multiprocess-safe via concurrent-log-handler

Author: jonfroehlich

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 `<BASE_DIR>/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — that's the tree bind-mounted to the shared CSE filesystem, so it's what makes the log readable over SSH at all. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. `MEDIA_ROOT` is web-served, so never log anything sensitive. 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 `<BASE_DIR>/media` (`/code/media` in the container). Keep it inside `MEDIA_ROOT` — that's the tree bind-mounted to the shared CSE filesystem, so it's what makes the log readable over SSH at all. `ML_LOG_DIR` is unset everywhere today; it exists for non-`/code` hosts. `MEDIA_ROOT` is web-served, so never log anything sensitive. 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-<uid>`), 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`)
 

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.32.0" # Keep this updated with each release and also change the short description below
-ML_WEBSITE_VERSION_DESCRIPTION = "Positions can now be titled \"Research Software Engineer\", and the affiliation fields are relabeled \"Institution or organization\" and \"Department or unit\" — collaborators come from nonprofits and companies, not just universities (#1437). This release also carries the 2.31.1 log-path fix (#1283)."
+ML_WEBSITE_VERSION = "2.32.1" # 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
 
@@ -122,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.
 
@@ -135,7 +151,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.
@@ -151,27 +167,82 @@ def _ensure_log_dir_writable(log_dir):
         return False
 
 
+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;
+       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
+
+
 def _file_log_handler(log_file, level, enabled):
     """Return the ``LOGGING['handlers']['file']`` config dict.
 
-    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.
-
-    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': 'logging.handlers.RotatingFileHandler',
         'filename': log_file,
         'maxBytes': 1024*1024*5,  # 5 MB
         'backupCount': 6,
         '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
@@ -247,6 +318,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 
@@ -269,6 +350,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',

makeabilitylab/settings_test.py

@@ -34,12 +34,15 @@
     "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
 # 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"]

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
 # -----------------------------------------------------------------------------