Skip to content

Gunicorn workers race on debug.log rotation, causing log loss #1439

Description

@jonfroehlich

Problem

Prod and test run 3 Gunicorn workers (docker-entrypoint.sh:211). Each worker process builds its own RotatingFileHandler from LOGGING and opens the same /code/media/debug.log, with no coordination. RotatingFileHandler is not multi-process safe, so the workers race on rollover and lose log records.

Found while verifying the #1283 deploy — not caused by it.

Evidence

Three concurrent writers on one file. PID counts in prod's live debug.log:

275 2997
252 2996
248 2995

Rollover happening far below the threshold. maxBytes is 5,242,880, but prod's rotated files are:

file size expected
debug.log.1 11,914 ~5,242,880
debug.log.2 11,737 ~5,242,880
debug.log.3 5,243,074
debug.log.4 188,786 ~5,242,880
debug.log.5 153,132 ~5,242,880
debug.log.6 5,243,158

Only 2 of 6 rotated at the real threshold.

Two rotated files with byte-identical mtimes on -test (12:08:43.659985323), plus out-of-order mtimes (debug.log.1 older than debug.log.2) — both signatures of concurrent rollover.

Mechanism

  1. Worker A crosses 5 MB, rotates: renames debug.log.1, creates a fresh empty debug.log.
  2. Workers B and C still hold file descriptors to the renamed inode and keep writing into it. Those records are now in .1 and will be shifted down the backup chain and dropped early.
  3. B's own stream crosses the threshold and B rotates too — but it renames whatever is currently named debug.log, which is A's nearly-empty new file. That is the 11 KB .1.

Options

  1. concurrent-log-handler (ConcurrentRotatingFileHandler) — drop-in, takes a file lock around rollover. Purpose-built for this. Cost: a new dependency.
  2. One file per worker — put the PID in filename. No shared file, no race. Cost: reading logs means merging; files accumulate across restarts. ⚠️ Also changes the on-disk filenames, which interacts with how debug.log is (not) exposed over the web — check that before choosing this.
  3. Stop rotating in Python — plain FileHandler, rotate once in docker-entrypoint.sh at container start (single process, no race). Cost: unbounded growth between deploys.

Leaning toward option 1.

Impact

Log records are silently lost, and rotated files no longer mean what they appear to. This makes debug.log unreliable exactly when it matters — diagnosing a production problem — and there is no shell access to these servers to compensate.

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions