The kept log: every process rotates postulo.log on its own, so one rotation becomes several and history is lost #379

New issue

Closed

opened 2026-10-01 10:46:16 +00:00 by tiagoagueda · 1 comment

tiagoagueda commented

2026-10-01 10:46:16 +00:00

Owner

Found on 2026-09-29 in a read-only review of postulo at 95348908d, reading the logging configuration, the image's process layout and the standard library's RotatingFileHandler.

Checked again on 2026-10-01 against main at 0a5cad587: still present.

Every Postulo process configures its own logging.handlers.RotatingFileHandler on the same postulo.log: the three gunicorn workers in the web container, and the scheduler and worker containers when their profiles are on, all on the one /app/data volume. The handler decides to rotate from the position of its own open file and renames the files without asking anybody else, which the Python logging cookbook states is unsupported across processes. One real rotation therefore turns into one rotation per process, the full generations are pushed off the end, and records land in files that are already rotated. Separately, the reader sorts rotations by name, so from ten backups on postulo.log.10 is read before postulo.log.2.

Where: config/settings/base.py:783-795 (the file handler, logging.handlers.RotatingFileHandler, configured identically in every process); core/logs.py:201-207 (files(): sorted(path.parent.glob(f"{path.name}.*"), key=lambda p: p.name)); docker/Dockerfile (--workers 3) and docker/compose.yml (the scheduler and worker services mount the same postulo-data volume).
What happens: with the defaults (POSTULO_LOG_MAX_BYTES 5 MB, POSTULO_LOG_BACKUPS 3) and three workers A, B and C:
1. A's next record would take postulo.log past 5 MB, so A renames .2→.3, .1→.2, postulo.log→.1, and opens a new postulo.log.
2. B and C still hold the renamed file, now .1. Their next record goes there, and the one after it finds their position near 5 MB, so each rotates in turn: the oldest two generations are deleted and the few lines A has written into the new file become .1, then .2.
3. A is now writing into a rotated file, and carries on doing so until that file reaches 5 MB itself.
After one real rotation the kept log holds one full generation instead of three, plus fragments, and Server settings → Logs and /logs read records out of order across files. With the scheduler and worker running the cascade is five long. Not reproduced here, because on Windows the rename fails instead; the sequence follows from shouldRollover using self.stream.tell() and doRollover renaming unconditionally.
Why it matters: the log is where an operator goes after something failed. POSTULO_LOG_MAX_BYTES × POSTULO_LOG_BACKUPS promises about 20 MB of history and delivers a fraction of it, straight after each rotation, and the page shows yesterday's error in the wrong place or not at all.
Fix: have one writer per file. Either give each process its own file (postulo-web-<pid>.log is awkward with gunicorn's recycling, so postulo-web.log through a WatchedFileHandler, postulo-scheduler.log, postulo-worker.log) and have files() merge them by time; or keep one file written by WatchedFileHandler in every process and rotate it from a single place (the scheduler, or the web container's entrypoint). Sort rotations by their numeric suffix in files().

Done when

A test in tests/test_logs.py creates postulo.log.1 to postulo.log.11 and asserts files() returns them in numeric order.
A test in tests/test_logs.py asserts that no process is configured to size-rotate a file another process writes: either the file handler in LOGGING names a file per process role, or it is a WatchedFileHandler and rotation happens in one place.
On Linux (skipped elsewhere), a test in tests/test_logs.py writes through two handlers configured as two processes would be, past the size limit, and asserts that every record written is still readable in time order.

Found on 2026-09-29 in a read-only review of postulo at 95348908d, reading the logging configuration, the image's process layout and the standard library's `RotatingFileHandler`. Checked again on 2026-10-01 against `main` at `0a5cad587`: still present. Every Postulo process configures its own `logging.handlers.RotatingFileHandler` on the same `postulo.log`: the three gunicorn workers in the web container, and the scheduler and worker containers when their profiles are on, all on the one `/app/data` volume. The handler decides to rotate from the position of its own open file and renames the files without asking anybody else, which the Python logging cookbook states is unsupported across processes. One real rotation therefore turns into one rotation per process, the full generations are pushed off the end, and records land in files that are already rotated. Separately, the reader sorts rotations by name, so from ten backups on `postulo.log.10` is read before `postulo.log.2`. - **Where:** `config/settings/base.py:783-795` (the `file` handler, `logging.handlers.RotatingFileHandler`, configured identically in every process); `core/logs.py:201-207` (`files()`: `sorted(path.parent.glob(f"{path.name}.*"), key=lambda p: p.name)`); `docker/Dockerfile` (`--workers 3`) and `docker/compose.yml` (the `scheduler` and `worker` services mount the same `postulo-data` volume). - **What happens:** with the defaults (`POSTULO_LOG_MAX_BYTES` 5 MB, `POSTULO_LOG_BACKUPS` 3) and three workers A, B and C: 1. A's next record would take `postulo.log` past 5 MB, so A renames `.2`→`.3`, `.1`→`.2`, `postulo.log`→`.1`, and opens a new `postulo.log`. 2. B and C still hold the renamed file, now `.1`. Their next record goes there, and the one after it finds their position near 5 MB, so each rotates in turn: the oldest two generations are deleted and the few lines A has written into the new file become `.1`, then `.2`. 3. A is now writing into a rotated file, and carries on doing so until that file reaches 5 MB itself. After one real rotation the kept log holds one full generation instead of three, plus fragments, and *Server settings → Logs* and `/logs` read records out of order across files. With the scheduler and worker running the cascade is five long. Not reproduced here, because on Windows the rename fails instead; the sequence follows from `shouldRollover` using `self.stream.tell()` and `doRollover` renaming unconditionally. - **Why it matters:** the log is where an operator goes after something failed. `POSTULO_LOG_MAX_BYTES` × `POSTULO_LOG_BACKUPS` promises about 20 MB of history and delivers a fraction of it, straight after each rotation, and the page shows yesterday's error in the wrong place or not at all. - **Fix:** have one writer per file. Either give each process its own file (`postulo-web-<pid>.log` is awkward with gunicorn's recycling, so `postulo-web.log` through a `WatchedFileHandler`, `postulo-scheduler.log`, `postulo-worker.log`) and have `files()` merge them by time; or keep one file written by `WatchedFileHandler` in every process and rotate it from a single place (the scheduler, or the web container's entrypoint). Sort rotations by their numeric suffix in `files()`. ## Done when - A test in `tests/test_logs.py` creates `postulo.log.1` to `postulo.log.11` and asserts `files()` returns them in numeric order. - A test in `tests/test_logs.py` asserts that no process is configured to size-rotate a file another process writes: either the `file` handler in `LOGGING` names a file per process role, or it is a `WatchedFileHandler` and rotation happens in one place. - On Linux (skipped elsewhere), a test in `tests/test_logs.py` writes through two handlers configured as two processes would be, past the size limit, and asserts that every record written is still readable in time order.

tiagoagueda added this to the 0.6.0 milestone

2026-10-01 10:46:16 +00:00

tiagoagueda added the

observability

bug

labels

2026-10-01 10:46:16 +00:00

tiagoagueda referenced this issue from a commit

2026-10-02 00:05:31 +00:00

Rotate the kept log one process at a time

tiagoagueda closed this issue

2026-10-02 00:05:31 +00:00

tiagoagueda referenced this issue from a commit

2026-10-02 00:05:31 +00:00

Hand a collector the oldest records after its mark, not the newest

tiagoagueda commented

2026-10-02 00:41:36 +00:00

Author

Owner

Landed as 258ae5ed8.

Fixed, and by neither of the two designs suggested above. Here is why.

A file per process role (postulo-web.log, postulo-scheduler.log, postulo-worker.log) still leaves gunicorn's three workers writing one file, so the web file needs exactly the coordination the single file needs, and the reader gains a merge by time across files. The entrypoint's manage.py runs (migrate, plugins sync, fetch_geonames, check --deploy) are further writers the issue did not list, each of which would need a role too.

One file, rotated from a single place needs a place that is always running. The scheduler is an optional Compose profile, so on a default install nothing would ever rotate; the web container's entrypoint runs once, at start.

What was done instead: every process still writes postulo.log, through postulo.core.logs.SharedRotatingFileHandler, which differs from the standard handler in two ways.

Before judging the file's size it lets go of its stream if the file at the path is no longer the one it holds, so it measures the live file and not a rotation another process made.
It renames only while holding an exclusive flock on postulo.log.lock, and looks again under the lock. A process that arrives behind another's rotation finds the path already changed and does nothing.

The lock is never waited for: a log call must not block on another process. If the lock is taken a rotation is under way, and the record is written to the stream in hand, which at worst is the file that has just become .1. It is kept, a few milliseconds out of place.

Where there is no fcntl (Windows, a developer's machine, one process) or the lock file cannot be created, the handler behaves as the standard one.

On the "Done when" list:

files() returns .1 to .11 in numeric order, and reads only all-digit suffixes, so the lock file is not mistaken for a rotation.
The second item asked that "no process is configured to size-rotate a file another process writes", either by a file per role or by WatchedFileHandler with rotation in one place. The test asserts instead that the configured handler is the shared one. That meets what the item is for, not its wording.
The Linux-only test with two handlers on one path is there, with three more: a handler asked to rotate after another already did makes no .2; a held lock is respected; and four real processes writing the same file lose nothing and push out no half-empty rotation.

Those four need a platform where an open file can be renamed, so they are skipped on Windows, where this was written. They ran and passed in CI on 17739fa1a (run 635, Python 3.12, 3.13 and 3.14).

Landed as `258ae5ed8`. Fixed, and by neither of the two designs suggested above. Here is why. **A file per process role** (`postulo-web.log`, `postulo-scheduler.log`, `postulo-worker.log`) still leaves gunicorn's three workers writing one file, so the web file needs exactly the coordination the single file needs, and the reader gains a merge by time across files. The entrypoint's `manage.py` runs (`migrate`, `plugins sync`, `fetch_geonames`, `check --deploy`) are further writers the issue did not list, each of which would need a role too. **One file, rotated from a single place** needs a place that is always running. The scheduler is an optional Compose profile, so on a default install nothing would ever rotate; the web container's entrypoint runs once, at start. **What was done instead:** every process still writes `postulo.log`, through `postulo.core.logs.SharedRotatingFileHandler`, which differs from the standard handler in two ways. - Before judging the file's size it lets go of its stream if the file at the path is no longer the one it holds, so it measures the live file and not a rotation another process made. - It renames only while holding an exclusive `flock` on `postulo.log.lock`, and looks again under the lock. A process that arrives behind another's rotation finds the path already changed and does nothing. The lock is never waited for: a log call must not block on another process. If the lock is taken a rotation is under way, and the record is written to the stream in hand, which at worst is the file that has just become `.1`. It is kept, a few milliseconds out of place. Where there is no `fcntl` (Windows, a developer's machine, one process) or the lock file cannot be created, the handler behaves as the standard one. **On the "Done when" list:** - `files()` returns `.1` to `.11` in numeric order, and reads only all-digit suffixes, so the lock file is not mistaken for a rotation. - The second item asked that "no process is configured to size-rotate a file another process writes", either by a file per role or by `WatchedFileHandler` with rotation in one place. The test asserts instead that the configured handler is the shared one. That meets what the item is for, not its wording. - The Linux-only test with two handlers on one path is there, with three more: a handler asked to rotate after another already did makes no `.2`; a held lock is respected; and four real processes writing the same file lose nothing and push out no half-empty rotation. Those four need a platform where an open file can be renamed, so they are skipped on Windows, where this was written. They ran and passed in CI on `17739fa1a` (run 635, Python 3.12, 3.13 and 3.14).