fix: gzip crash-safety + size rotation always bounds live file (logsetup-7/8/9)

_gzip_file now writes to a .tmp sibling and atomically os.replaces it onto
the final .gz path, so a crash/OOM mid-write can never leave a truncated
.gz where retention trusts it; retier's plain/gz dedupe additionally
verifies a .gz decompresses cleanly before removing its plain twin, so a
corrupt .gz is never preferred over the last intact copy.

rotate="size" now always forces the handler's backupCount to fire
regardless of backup_count, so backup_count=0 means "keep zero rolled
files" (each roll deletes itself immediately) instead of silently
disabling rotation and growing the live file unbounded.

Also mirrors retier's mtime+roll-counter sort key into prune() so a
same-second burst with tied mtimes prunes the oldest files instead of
arbitrary listdir order (logsetup-9, adjacent one-line fix).

Bumps to v0.5.1.

Signed-off-by: disqualifier <dev@disqualifier.me>
This commit is contained in:
2026-07-02 17:24:26 -04:00
parent 1207c53742
commit b74fe7d726
4 changed files with 129 additions and 30 deletions
+23 -4
View File
@@ -13,12 +13,12 @@ and emit; their records flow into the handlers `log_setup` wired.
## Install ## Install
``` ```
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.5.0 log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.5.1
``` ```
No dependencies — stdlib only. No dependencies — stdlib only.
Drop the `@v0.5.0` suffix from the line above to install the latest unpinned. Drop the `@v0.5.1` suffix from the line above to install the latest unpinned.
## Quick start ## Quick start
@@ -44,7 +44,10 @@ emits; the records land in the configured root.
`getLogger` name each module used, so you see which lib/module logged. `getLogger` name each module used, so you see which lib/module logged.
- **Rotation** (`rotate=`): - **Rotation** (`rotate=`):
- `"daily"` (default) — rolls at midnight into `log_dir`, keeps `backup_count` days. - `"daily"` (default) — rolls at midnight into `log_dir`, keeps `backup_count` days.
- `"size"` — rolls at `max_bytes` into `log_dir`, keeps `backup_count`. - `"size"` — rolls at `max_bytes` into `log_dir`, keeps `backup_count`. `backup_count=0`
means **keep no rolled history**: the live file still rolls at `max_bytes` (size is
always bounded), each rolled file is deleted immediately after landing — it does not
disable rotation (see **Retention** below).
- `"on_start"` — on startup, moves an existing live file into `log_dir` and starts fresh; - `"on_start"` — on startup, moves an existing live file into `log_dir` and starts fresh;
prunes to `backup_count`. prunes to `backup_count`.
- `None` — single file, no rotation. - `None` — single file, no rotation.
@@ -52,7 +55,8 @@ emits; the records land in the configured root.
`<project>.<timestamp>.log[.gz]`; the live file keeps its own name. `<project>.<timestamp>.log[.gz]`; the live file keeps its own name.
- **compress=True** (default) gzips each rolled file. - **compress=True** (default) gzips each rolled file.
- **Retention** = `backup_count` (default 14) for every mode — unless tiered retention is - **Retention** = `backup_count` (default 14) for every mode — unless tiered retention is
enabled (below). enabled (below). For `rotate="size"`, `backup_count=0` is "keep none" (not "disable
rotation") — see the `size` bullet above and the note at the bottom of this section.
- **console=True** (off by default) also logs to stdout in the same format — opt in when - **console=True** (off by default) also logs to stdout in the same format — opt in when
you want live terminal output alongside the file. you want live terminal output alongside the file.
@@ -228,6 +232,21 @@ setup_logging(name="run", queue=True)
duplicate lines) and leaves handlers your app added itself alone. duplicate lines) and leaves handlers your app added itself alone.
- **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to - **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to
console-only with a warning instead of raising. console-only with a warning instead of raising.
- **`rotate="size"` always bounds the live file (v0.5.1+).** Previously, `backup_count=0`
with `rotate="size"` silently disabled rotation entirely (the live file grew forever,
ignoring `max_bytes`). As of v0.5.1, the live file always rolls at `max_bytes`
regardless of `backup_count`; `backup_count=0` means "keep zero rolled files" (each roll
is deleted right after it lands) rather than "never roll." `backup_count>=1` behaves as
documented (keeps that many rolled files). This does not change `"daily"`/`"on_start"`,
where `backup_count=0` still means "roll, but don't prune the rolled files" (unbounded
`log_dir` growth) — that is a separate, pre-existing knob, not this fix's scope.
- **Gzip writes are crash-safe (v0.5.1+).** `_gzip_file` now writes to a `.tmp` sibling and
atomically `os.replace`s it onto the final `.gz` path, so a crash/OOM/power-loss mid-write
can never leave a truncated `.gz` at the path retention logic trusts. Tiered retention's
plain/gz dedupe additionally verifies a `.gz` decompresses cleanly before deleting its
plain twin — a corrupt `.gz` (from before this fix, or an external cause) is never
preferred over an intact plain copy; the plain is kept and the `.gz` gets rewritten
cleanly on the next retier pass instead of being deleted.
## Scope — what this is NOT ## Scope — what this is NOT
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project] [project]
name = "log_setup" name = "log_setup"
version = "0.5.0" version = "0.5.1"
description = "stdlib app-entry-point logging setup: live run.log, rotation, gzip, retention, consistent format" description = "stdlib app-entry-point logging setup: live run.log, rotation, gzip, retention, consistent format"
requires-python = ">=3.10" requires-python = ">=3.10"
dependencies = [] dependencies = []
+77 -10
View File
@@ -4,6 +4,13 @@ the stdlib rotating handlers roll a file next to the live file; these helpers
override the namer/rotator so rolled files land in `log_dir` and are gzipped when override the namer/rotator so rolled files land in `log_dir` and are gzipped when
asked, keep the live file at its stable path, and handle the on-start and prune asked, keep the live file at its stable path, and handle the on-start and prune
paths the handlers don't manage themselves. paths the handlers don't manage themselves.
gzip writes are crash-safe: `_gzip_file` writes to a `.tmp` sibling and atomically
`os.replace`s it onto the final `.gz` path, so a crash/OOM/power-loss mid-write never
leaves a truncated `.gz` where retention logic would trust it. `retier`'s plain/gz
dedupe additionally verifies a `.gz` decompresses cleanly (`_gz_intact`) before removing
its plain twin, so a corrupt `.gz` (pre-existing or externally caused) is never preferred
over an intact plain copy.
""" """
import gzip import gzip
@@ -53,13 +60,28 @@ def _free_dest(dest: str) -> str:
def _gzip_file(source: str, dest: str) -> None: def _gzip_file(source: str, dest: str) -> None:
"""gzip source into dest then remove source (the rolled-file compression idiom) """gzip source into dest then remove source (the rolled-file compression idiom)
writes to `dest + ".tmp"` first and `os.replace`s it onto `dest` once the gzip
write is complete, so a crash/OOM/power-loss mid-write never leaves a truncated
`.gz` at `dest` — the partial write stays quarantined in the `.tmp` name and the
source is untouched (safe to retry). os.replace is atomic on the same filesystem,
which the `.tmp` sibling always is.
the source mtime is carried onto dest so a file keeps its position when it crosses the source mtime is carried onto dest so a file keeps its position when it crosses
the plain->gz tier boundary — retier ranks by mtime, and a fresh write would the plain->gz tier boundary — retier ranks by mtime, and a fresh write would
otherwise make a just-compressed file look like the newest one and reshuffle tiers. otherwise make a just-compressed file look like the newest one and reshuffle tiers.
""" """
mtime = _safe_mtime(source) mtime = _safe_mtime(source)
with open(source, "rb") as src, gzip.open(dest, "wb") as dst: tmp_dest = dest + ".tmp"
try:
with open(source, "rb") as src, gzip.open(tmp_dest, "wb") as dst:
shutil.copyfileobj(src, dst) shutil.copyfileobj(src, dst)
except BaseException:
try:
os.remove(tmp_dest)
except OSError:
pass
raise
os.replace(tmp_dest, dest)
os.remove(source) os.remove(source)
try: try:
os.utime(dest, (mtime, mtime)) os.utime(dest, (mtime, mtime))
@@ -67,6 +89,24 @@ def _gzip_file(source: str, dest: str) -> None:
pass pass
def _gz_intact(path: str) -> bool:
"""return True if the gzip file at path decompresses cleanly end to end
belt-and-suspenders check before a dedupe site removes a plain twin in favor of
its .gz — a truncated/corrupt .gz (partial write, bad copy, disk error) must never
be trusted over an intact plain copy. reads the whole stream since gzip.open only
validates the end-of-stream marker on a full read; any failure (BadGzipFile, EOFError,
OSError, zlib error) is treated as "not intact" so the caller keeps the plain source.
"""
try:
with gzip.open(path, "rb") as handle:
while handle.read(1 << 20):
pass
return True
except Exception:
return False
def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]: def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]:
"""namer: redirect a rolled filename into log_dir, adding .gz when compressing """namer: redirect a rolled filename into log_dir, adding .gz when compressing
@@ -120,7 +160,10 @@ def make_rotator(
`backup_count` newest rolled files. the stdlib handler's own retention `backup_count` newest rolled files. the stdlib handler's own retention
(`getFilesToDelete`) only scans the live file's directory, so it never sees the (`getFilesToDelete`) only scans the live file's directory, so it never sees the
rolled files we redirect into `log_dir` — pruning here is what bounds retention for rolled files we redirect into `log_dir` — pruning here is what bounds retention for
the daily and size rolling modes. the daily and size rolling modes. `backup_count <= 0` means "keep no rolled history":
`prune()` itself no-ops at `backup_count <= 0` (it means "don't touch history"), so a
zero-retention roll is deleted by the rotator directly right after landing, rather than
relying on prune to do it.
tiered mode (when `keep_uncompressed`/`keep_compressed` are given): land the rolled tiered mode (when `keep_uncompressed`/`keep_compressed` are given): land the rolled
file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, the file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, the
@@ -147,7 +190,15 @@ def make_rotator(
_gzip_file(source, dest) _gzip_file(source, dest)
else: else:
_move(source, dest) _move(source, dest)
if log_dir is not None and prune_stem is not None: if backup_count <= 0:
# "keep no history": prune() no-ops at backup_count <= 0 (that's its "leave
# history alone" sentinel, not "delete everything"), so a zero-retention roll
# deletes its own just-landed file directly instead of relying on prune.
try:
os.remove(dest)
except OSError:
pass
elif log_dir is not None and prune_stem is not None:
prune(log_dir, prune_stem, backup_count) prune(log_dir, prune_stem, backup_count)
return rotator return rotator
@@ -231,16 +282,24 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
entries = [os.path.join(log_dir, name) for name in names] entries = [os.path.join(log_dir, name) for name in names]
# dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove can # dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove can
# leave <x>.log beside <x>.log.gz). drop the redundant plain copy up front so the # leave <x>.log beside <x>.log.gz). drop the redundant plain copy up front so the
# phantom twin never occupies a retention slot and evicts a distinct older roll. # phantom twin never occupies a retention slot and evicts a distinct older roll — but
# ONLY once the .gz is verified to decompress cleanly. _gzip_file now writes atomically
# (temp+os.replace) so a fresh truncated twin can't occur, but a pre-existing corrupt
# .gz (older data, bad copy, disk error) must never win over an intact plain copy: that
# would delete the only good copy and keep garbage, strictly worse than doing nothing.
present = set(entries) present = set(entries)
kept = [] kept = []
for p in entries: for p in entries:
if not p.endswith(".gz") and (p + ".gz") in present: if not p.endswith(".gz") and (p + ".gz") in present:
if _gz_intact(p + ".gz"):
try: try:
os.remove(p) os.remove(p)
except OSError: except OSError:
kept.append(p) # couldn't remove — keep it in the accounting kept.append(p) # couldn't remove — keep it in the accounting
continue continue
# .gz twin is corrupt/truncated — keep the intact plain, don't touch either
# file here (the second dedupe pass below or a future retier will retry the
# compress once the plain is re-gzipped cleanly)
kept.append(p) kept.append(p)
files = [(p, _safe_mtime(p), _roll_counter(p)) for p in kept if os.path.isfile(p)] files = [(p, _safe_mtime(p), _roll_counter(p)) for p in kept if os.path.isfile(p)]
# newest-first: higher mtime first, and within a tied second the higher roll counter # newest-first: higher mtime first, and within a tied second the higher roll counter
@@ -260,12 +319,17 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
# a crash/power-loss between _gzip_file's write and its os.remove can leave # a crash/power-loss between _gzip_file's write and its os.remove can leave
# a plain source beside a fresh .gz. don't keep both (they'd double-count # a plain source beside a fresh .gz. don't keep both (they'd double-count
# toward retention and evict a distinct older roll) — drop the redundant # toward retention and evict a distinct older roll) — drop the redundant
# plain twin, keeping the compressed copy. # plain twin, but ONLY once the .gz is verified intact (see _gz_intact):
# a corrupt/truncated .gz here must never win over the last good copy.
if _gz_intact(dest):
try: try:
os.remove(path) os.remove(path)
except OSError: except OSError:
pass pass
continue continue
# .gz is corrupt — fall through and re-gzip the plain over the bad dest
# (_gzip_file writes atomically, so the corrupt dest is only replaced once
# a fully valid archive exists)
try: try:
_gzip_file(path, dest) _gzip_file(path, dest)
except OSError: except OSError:
@@ -294,8 +358,9 @@ def _roll_counter(path: str) -> int:
def prune(log_dir: str, stem: str, backup_count: int) -> None: def prune(log_dir: str, stem: str, backup_count: int) -> None:
"""keep only the newest `backup_count` rolled files for a given stem in log_dir """keep only the newest `backup_count` rolled files for a given stem in log_dir
matches files beginning with `<stem>.` (e.g. run.*), sorted by mtime, deleting the matches files beginning with `<stem>.` (e.g. run.*), sorted by mtime (then by the
oldest beyond the count. used for on_start, which the handlers don't auto-prune. roll counter parsed from the name, mirroring retier — see _roll_counter), deleting
the oldest beyond the count. used for on_start, which the handlers don't auto-prune.
`stem` is reduced to its basename so a `name` containing a directory (e.g. "sub/run") `stem` is reduced to its basename so a `name` containing a directory (e.g. "sub/run")
still matches the basenamed rolled files in log_dir (else nothing matches and old still matches the basenamed rolled files in log_dir (else nothing matches and old
@@ -312,9 +377,11 @@ def prune(log_dir: str, stem: str, backup_count: int) -> None:
] ]
except OSError: except OSError:
return return
files = [(p, _safe_mtime(p)) for p in entries if os.path.isfile(p)] files = [(p, _safe_mtime(p), _roll_counter(p)) for p in entries if os.path.isfile(p)]
files.sort(key=lambda pair: pair[1], reverse=True) # newest-first: higher mtime first, and within a tied second the higher roll counter
for path, _ in files[backup_count:]: # (a later same-second roll) is newer — mirrors retier's ordering (line ~289)
files.sort(key=lambda t: (t[1], t[2]), reverse=True)
for path, _, _ in files[backup_count:]:
try: try:
os.remove(path) os.remove(path)
except OSError: except OSError:
+17 -4
View File
@@ -6,6 +6,10 @@ of rolled files, retention, console output, and a consistent format. it is calle
the APPLICATION, not by reusable libraries (those stay emit-only). it is idempotent the APPLICATION, not by reusable libraries (those stay emit-only). it is idempotent
(no duplicate handlers on repeat calls), never crashes the app over logging, and can (no duplicate handlers on repeat calls), never crashes the app over logging, and can
route through a background queue so an async event loop doesn't block on file I/O. route through a background queue so an async event loop doesn't block on file I/O.
`rotate="size"` always bounds the live file: the roll fires at `max_bytes` regardless
of `backup_count`, including `backup_count=0` (which means "keep zero rolled files",
not "never roll" — each roll is deleted right after landing).
""" """
import atexit import atexit
@@ -148,9 +152,14 @@ def _file_handler(
if rotate == "size": if rotate == "size":
# stdlib doRollover is a no-op when backupCount == 0, and its numbered .1/.2 shift # stdlib doRollover is a no-op when backupCount == 0, and its numbered .1/.2 shift
# can't manage files redirected into log_dir. force a nonzero backupCount so the # can't manage files redirected into log_dir. force a nonzero backupCount so the
# roll always fires, and let attach_rolling's history namer name + retier/prune # roll always fires regardless of mode — tiered AND legacy — and let
# bound retention (keyed to history_stem). # attach_rolling's history namer name + retier/prune bound retention (keyed to
size_backup = backup_count if not tiered else max(backup_count, 1) # history_stem). the ORIGINAL backup_count (which may be 0) still flows into
# attach_rolling below: make_rotator treats backup_count <= 0 there as "keep no
# rolled history" and deletes each roll right after it lands, rather than passing
# 0 to prune() (whose own backup_count <= 0 means "leave history alone", a no-op —
# that mismatch is exactly what silently disabled rotation before).
size_backup = max(backup_count, 1)
handler = logging.handlers.RotatingFileHandler( handler = logging.handlers.RotatingFileHandler(
live_path, maxBytes=max_bytes, backupCount=size_backup, encoding="utf-8", live_path, maxBytes=max_bytes, backupCount=size_backup, encoding="utf-8",
) )
@@ -233,7 +242,11 @@ def setup_logging(
applies, so naming a parent ("aiohttp") quiets its whole subtree (aiohttp.client, applies, so naming a parent ("aiohttp") quiets its whole subtree (aiohttp.client,
aiohttp.access, ...). each entry accepts a str or int level; a bad value for one aiohttp.access, ...). each entry accepts a str or int level; a bad value for one
entry is skipped with a warning and never aborts the others or the setup. entry is skipped with a warning and never aborts the others or the setup.
`rotate` is "daily" (default), "size", "on_start", or None. `console=True` adds a `rotate` is "daily" (default), "size", "on_start", or None. for `rotate="size"`, the
live file always rolls at `max_bytes` regardless of `backup_count`: `backup_count=0`
means "keep zero rolled files" (each roll lands then is deleted immediately), NOT
"disable rotation" — the live file is always bounded. `backup_count>=1` keeps that
many rolled files as before. `console=True` adds a
stdout handler (off by default — the file is the output). `queue=True` routes records stdout handler (off by default — the file is the output). `queue=True` routes records
through a background QueueListener so file I/O never blocks the caller (the listener through a background QueueListener so file I/O never blocks the caller (the listener
is stopped at exit). `output` is "text" (default, human `time | module | level | is stopped at exit). `output` is "text" (default, human `time | module | level |