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:
@@ -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
@@ -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
@@ -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
@@ -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 |
|
||||||
|
|||||||
Reference in New Issue
Block a user