diff --git a/README.md b/README.md index 380ec14..b1da584 100644 --- a/README.md +++ b/README.md @@ -13,12 +13,12 @@ and emit; their records flow into the handlers `log_setup` wired. ## 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. -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 @@ -44,7 +44,10 @@ emits; the records land in the configured root. `getLogger` name each module used, so you see which lib/module logged. - **Rotation** (`rotate=`): - `"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; prunes to `backup_count`. - `None` — single file, no rotation. @@ -52,7 +55,8 @@ emits; the records land in the configured root. `..log[.gz]`; the live file keeps its own name. - **compress=True** (default) gzips each rolled file. - **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 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. - **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to 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 diff --git a/pyproject.toml b/pyproject.toml index 6f05c36..e327fb7 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] 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" requires-python = ">=3.10" dependencies = [] diff --git a/src/log_setup/rotation.py b/src/log_setup/rotation.py index 958b6a8..ede4626 100644 --- a/src/log_setup/rotation.py +++ b/src/log_setup/rotation.py @@ -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 asked, keep the live file at its stable path, and handle the on-start and prune 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 @@ -53,13 +60,28 @@ def _free_dest(dest: str) -> str: def _gzip_file(source: str, dest: str) -> None: """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 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. """ mtime = _safe_mtime(source) - with open(source, "rb") as src, gzip.open(dest, "wb") as dst: - shutil.copyfileobj(src, dst) + tmp_dest = dest + ".tmp" + try: + with open(source, "rb") as src, gzip.open(tmp_dest, "wb") as dst: + shutil.copyfileobj(src, dst) + except BaseException: + try: + os.remove(tmp_dest) + except OSError: + pass + raise + os.replace(tmp_dest, dest) os.remove(source) try: os.utime(dest, (mtime, mtime)) @@ -67,6 +89,24 @@ def _gzip_file(source: str, dest: str) -> None: 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]: """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 (`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 - 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 file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, the @@ -147,7 +190,15 @@ def make_rotator( _gzip_file(source, dest) else: _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) 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] # dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove can # leave .log beside .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) kept = [] for p in entries: if not p.endswith(".gz") and (p + ".gz") in present: - try: - os.remove(p) - except OSError: - kept.append(p) # couldn't remove — keep it in the accounting - continue + if _gz_intact(p + ".gz"): + try: + os.remove(p) + except OSError: + kept.append(p) # couldn't remove — keep it in the accounting + 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) 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 @@ -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 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 - # plain twin, keeping the compressed copy. - try: - os.remove(path) - except OSError: - pass - continue + # 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: + os.remove(path) + except OSError: + pass + 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: _gzip_file(path, dest) except OSError: @@ -294,8 +358,9 @@ def _roll_counter(path: str) -> int: 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 - matches files beginning with `.` (e.g. run.*), sorted by mtime, deleting the - oldest beyond the count. used for on_start, which the handlers don't auto-prune. + matches files beginning with `.` (e.g. run.*), sorted by mtime (then by the + 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") 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: return - files = [(p, _safe_mtime(p)) for p in entries if os.path.isfile(p)] - files.sort(key=lambda pair: pair[1], reverse=True) - for path, _ in files[backup_count:]: + files = [(p, _safe_mtime(p), _roll_counter(p)) for p in entries if os.path.isfile(p)] + # newest-first: higher mtime first, and within a tied second the higher roll counter + # (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: os.remove(path) except OSError: diff --git a/src/log_setup/setup.py b/src/log_setup/setup.py index b4a8bf3..dc2d0ef 100644 --- a/src/log_setup/setup.py +++ b/src/log_setup/setup.py @@ -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 (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. + +`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 @@ -148,9 +152,14 @@ def _file_handler( if rotate == "size": # 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 - # roll always fires, and let attach_rolling's history namer name + retier/prune - # bound retention (keyed to history_stem). - size_backup = backup_count if not tiered else max(backup_count, 1) + # roll always fires regardless of mode — tiered AND legacy — and let + # attach_rolling's history namer name + retier/prune bound retention (keyed to + # 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( 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, 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. - `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 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 |