From 93994da9d69a1303857b3ee997639ba5df85ef38 Mon Sep 17 00:00:00 2001 From: disqualifier Date: Thu, 2 Jul 2026 23:30:01 -0400 Subject: [PATCH] fix: setup-time warnings reach the log; add JSON ts field; compress docstrings (logsetup-10/11/12) Setup-time warnings (invalid module_levels entry, handler-close failure on re-setup, unknown rotate) fired before any handler attached, so they hit stderr via logging's lastResort and never run.log; now buffered and flushed after handlers attach (logsetup-10). README's tiered-retention example showed the wrong historic-file naming and put the live file inside log_dir; corrected to the actual project-stem naming and cwd location (logsetup-11). Package docstring claimed console output by default; console=False is the real default (logsetup-12). JSON output gains an additive ts field (unix epoch int, alongside the unchanged ISO time) for consumers that want a sortable number. Compressed essay-length docstrings/comments across setup.py, rotation.py, and formats.py with zero behavior change (re-verified against baseline logs/ listings); load-bearing footgun notes kept. Signed-off-by: disqualifier --- README.md | 43 +++++--- pyproject.toml | 2 +- src/log_setup/__init__.py | 8 +- src/log_setup/formats.py | 25 +++-- src/log_setup/rotation.py | 208 +++++++++++++++++--------------------- src/log_setup/setup.py | 190 +++++++++++++++++++--------------- 6 files changed, 252 insertions(+), 224 deletions(-) diff --git a/README.md b/README.md index b1da584..a46ebb4 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.1 +log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.0 ``` No dependencies — stdlib only. -Drop the `@v0.5.1` suffix from the line above to install the latest unpinned. +Drop the `@v0.6.0` suffix from the line above to install the latest unpinned. ## Quick start @@ -92,6 +92,7 @@ are deleted past the count. If instead you want the recent logs **uncompressed** without `zcat`) and older ones **gzipped**, pass the two tier knobs: ```python +# app run from bestbuy/run.py , with name="latest": setup_logging( name="latest", rotate="on_start", # works for on_start, daily, and size @@ -100,13 +101,15 @@ setup_logging( ) ``` -Result in `log_dir` (newest → oldest): +Result — the live file stays at its stable path in cwd; `log_dir` (default `logs/`) holds +the tiered historic files, named off the project stem (newest → oldest): ``` -latest.log <- live "latest" (stable, tail -f) -latest..log latest..log latest..log <- 3 newest: plain -latest..log.gz ... latest..log.gz <- next 7: gzipped -(anything past 10 deleted) +./latest.log <- live (stable, tail -f, in cwd) +logs/ + bestbuy..log bestbuy..log bestbuy..log <- 3 newest: plain + bestbuy..log.gz ... bestbuy..log.gz <- next 7: gzipped + (anything past 10 deleted) ``` - Each restart (`on_start`) or roll (`daily`/`size`) moves the live file into `log_dir`, @@ -136,17 +139,22 @@ Promtail glob, bind-mount path, or your `tail` command. ```python setup_logging(name="run", output="json") logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"}) -# -> {"time": "2026-06-28T14:03:11Z", "level": "INFO", "module": "bot.core", -# "message": "ready", "monitor": "heartbeat"} +# -> {"time": "2026-06-28T14:03:11Z", "ts": 1782151391, "level": "INFO", +# "module": "bot.core", "message": "ready", "monitor": "heartbeat"} ``` -- **Fields:** `time`, `level`, `module`, `message` always; any `extra={...}` keys land - as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels — the lib - stays domain-agnostic); error records carry the traceback in `exc_info` (never dropped). +- **Fields:** `time`, `ts`, `level`, `module`, `message` always; any `extra={...}` keys + land as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels — + the lib stays domain-agnostic); error records carry the traceback in `exc_info` (never + dropped). - **Time is UTC ISO-8601 with a `Z`** (`2026-06-28T14:03:11Z`), not local. json is the aggregation path — logs from many servers/containers sort unambiguously only in UTC; Grafana converts to local for display. (Text mode stays local — that's a human on one box.) +- **`ts` (added v0.6.0)** is the same instant as a unix epoch integer + (`int(record.created)`, second resolution) alongside `time` — for a consumer that wants + a sortable number instead of parsing the ISO string. Additive: existing `time` is + unchanged, and a consumer that ignores unknown JSON keys is unaffected. - Both file and console use the chosen format. `fmt`/`datefmt` apply to text only (json builds fields, not a format string). An unknown `output` falls back to text + warns, never crashes. **Zero new deps** — stdlib `json` only. @@ -247,6 +255,17 @@ setup_logging(name="run", queue=True) 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. +- **Setup-time warnings reach the log file (v0.6.0+).** Previously, a warning raised + during `setup_logging` itself (an invalid `module_levels` entry, a handler failing to + close on re-setup, an unknown `rotate` value) was emitted *before* any handler was + attached, so it only reached stderr via logging's `lastResort` fallback and never + `run.log`. As of v0.6.0 these are buffered and flushed once the handlers are attached, + so they land in the configured log like any other record. +- **JSON output gained a `ts` field (v0.6.0, additive).** Alongside the existing `time` + (UTC ISO-8601, unchanged), each JSON line now also carries `ts`: the same instant as a + unix epoch integer (`int(record.created)`, second resolution) — for a consumer that + wants a sortable number instead of parsing the ISO string. Purely additive: `time` is + byte-for-byte unchanged, and a consumer that ignores unknown JSON keys is unaffected. ## Scope — what this is NOT diff --git a/pyproject.toml b/pyproject.toml index e327fb7..a3f6f41 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "log_setup" -version = "0.5.1" +version = "0.6.0" 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/__init__.py b/src/log_setup/__init__.py index 0c624c7..9fdf6e8 100644 --- a/src/log_setup/__init__.py +++ b/src/log_setup/__init__.py @@ -1,14 +1,14 @@ """log_setup — app-entry-point logging configuration (sync, stdlib only). call once at an application's entry point to configure the whole process: a live -run.log, rotation (daily/size/on_start), gzip of rolled files, retention, console -output, and a consistent `time | module | level | message` format. +run.log, rotation (daily/size/on_start), gzip of rolled files, retention, optional +console output, and a consistent `time | module | level | message` format. from log_setup import setup_logging setup_logging(name="run", level="INFO") # daily rotation, logs/ dir, gzip log = logging.getLogger(__name__) - log.info("up") # -> run.log + console + log.info("up") # -> run.log (add console=True for stdout too) reusable libraries do NOT call this — they only `logging.getLogger(__name__)` and emit; the application owns this setup. shipping logs to a backend is out of scope @@ -19,4 +19,4 @@ from .setup import setup_logging __all__ = ["setup_logging"] -__version__ = "0.5.0" +__version__ = "0.6.0" diff --git a/src/log_setup/formats.py b/src/log_setup/formats.py index 9e1c071..97b941a 100644 --- a/src/log_setup/formats.py +++ b/src/log_setup/formats.py @@ -16,28 +16,31 @@ DEFAULT_DATEFMT = "%Y-%m-%d %H:%M:%S" _RESERVED = frozenset(vars(logging.makeLogRecord({})).keys()) | {"message", "asctime"} # this formatter's own canonical output keys — stdlib's LogRecord rejects `extra` keys -# colliding with real attribute names (e.g. `module`), but `time`/`level` are NOT -# LogRecord attrs, so a caller's extra={"time":...}/{"level":...} would otherwise -# overwrite the UTC timestamp / levelname. guard them explicitly -_OUTPUT_KEYS = frozenset({"time", "level", "module", "message"}) +# colliding with real attribute names (e.g. `module`), but `time`/`level`/`ts` are NOT +# LogRecord attrs, so a caller's extra={"time":...}/{"ts":...} would otherwise overwrite +# the UTC timestamp / epoch. guard them explicitly +_OUTPUT_KEYS = frozenset({"time", "ts", "level", "module", "message"}) class JsonLinesFormatter(logging.Formatter): """format each record as a single-line JSON object (JSON Lines / .jsonl) - emits at minimum time/level/module/message. time is UTC ISO-8601 with a `Z` - suffix (e.g. 2026-06-28T14:03:11Z) so logs aggregated across machines and - containers sort unambiguously — Grafana converts to local for display. any - field passed via logging `extra={...}` lands as a top-level JSON field, which - is how a caller stamps monitor/service/request-id for Loki labels without the - lib knowing those domain concepts. a traceback (exc_info) is rendered into an - `exc_info` string field rather than dropped. + emits at minimum time/ts/level/module/message. `time` is UTC ISO-8601 with a `Z` + suffix (e.g. 2026-06-28T14:03:11Z); `ts` (added v0.6.0) is the same instant as a + unix epoch int (`int(record.created)`, second resolution) for a consumer that wants + a sortable number instead of parsing the ISO string — both sort unambiguously + across machines/containers; Grafana converts to local for display. any field + passed via logging `extra={...}` lands as a top-level JSON field (how a caller + stamps monitor/service/request-id for Loki labels without the lib knowing those + domain concepts). a traceback (exc_info) is rendered into an `exc_info` string + field rather than dropped. """ def format(self, record: logging.LogRecord) -> str: when = datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc) payload = { "time": when.strftime("%Y-%m-%dT%H:%M:%SZ"), + "ts": int(record.created), "level": record.levelname, "module": record.name, "message": record.getMessage(), diff --git a/src/log_setup/rotation.py b/src/log_setup/rotation.py index ede4626..5c0e305 100644 --- a/src/log_setup/rotation.py +++ b/src/log_setup/rotation.py @@ -1,16 +1,15 @@ """custom namer/rotator + on-start rotation + retention pruning (stdlib only). -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. +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. +leaves a truncated `.gz` where retention 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` is never preferred over an intact plain copy. """ import gzip @@ -23,15 +22,13 @@ from typing import Callable, Optional, Tuple def _move(source: str, dest: str) -> None: """rename source to dest, falling back to copy+unlink across filesystems - os.replace is atomic but raises OSError(EXDEV) when source and dest are on - different filesystems — exactly the container bind-mount / separate-logs-volume - case this lib targets. fall back to shutil.move (copy+unlink) so the roll still - lands instead of failing every rotation via the handler's silent handleError. + os.replace is atomic but raises OSError(EXDEV) across filesystems — the container + bind-mount / separate-logs-volume case this lib targets. falls back to shutil.move + (copy+unlink) so the roll still lands instead of failing rotation silently. - precondition: `dest` is a free, non-directory path (all call sites generate a unique - timestamped/dated dest). os.replace and shutil.move differ on a dest that already - exists as a directory, so this helper is not safe for arbitrary dests — only the - rotation paths that guarantee a fresh file dest. + precondition: `dest` is a free, non-directory path (every call site generates a + unique timestamped/dated dest) — not safe for arbitrary dests that may already + exist as a directory. """ try: os.replace(source, dest) @@ -43,9 +40,8 @@ def _free_dest(dest: str) -> str: """return `dest`, or a `.N`-suffixed variant if it (or its .gz twin) already exists used by the tiered rotator so a second roll landing on the same dated/stamped name - (e.g. two daily rolls in one day) doesn't clobber the earlier file. the suffix goes - before nothing here (dest is already the plain path) — checks both the plain and .gz - forms of each candidate. + (two daily rolls in one day) doesn't clobber the earlier file. checks both the plain + and .gz forms of each candidate. """ if not os.path.exists(dest) and not os.path.exists(dest + ".gz"): return dest @@ -60,15 +56,14 @@ 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. + writes to `dest + ".tmp"` and atomically `os.replace`s it onto `dest` once + complete, so a crash/OOM/power-loss mid-write never leaves a truncated `.gz` at + `dest` — the partial write stays quarantined in `.tmp` and source is untouched + (safe to retry). - 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. + the source mtime is carried onto dest so a file keeps its tier position when it + crosses the plain->gz boundary — retier ranks by mtime, and a fresh write would + otherwise make a just-compressed file look newest and reshuffle tiers. """ mtime = _safe_mtime(source) tmp_dest = dest + ".tmp" @@ -92,11 +87,10 @@ def _gzip_file(source: str, dest: str) -> None: 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. + belt-and-suspenders check before a dedupe site removes a plain twin in favor of its + .gz — a truncated/corrupt .gz must never be trusted over an intact plain copy. reads + the whole stream (gzip.open only validates end-of-stream on a full read); any + failure is treated as "not intact" so the caller keeps the plain source. """ try: with gzip.open(path, "rb") as handle: @@ -110,8 +104,8 @@ def _gz_intact(path: str) -> bool: def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]: """namer: redirect a rolled filename into log_dir, adding .gz when compressing - the handler hands us the default rolled path (next to the live file); we keep its - basename but place it under log_dir, and append .gz so the gzipped name matches. + keeps the handler's default rolled basename but places it under log_dir, appending + .gz so the gzipped name matches. """ def namer(default_name: str) -> str: base = os.path.basename(default_name) @@ -127,14 +121,14 @@ def make_history_namer( """namer minting historic rolled files `..log[.gz]` in log_dir used by size and daily (and their tiered variants). `stem` is the HISTORY stem (the - project namespace), independent of the live file's name — the returned rolled files - are keyed off it, and prune/retier glob the same stem. + project namespace), independent of the live file's name. FOOTGUN: prune/retier must + glob this same stem or nothing matches and retention silently never fires. - the stdlib handler's own rolled name (`.N` for size, `.log.` for daily) is - ignored — we mint our own uniform timestamped name so all modes converge on one shape - and retier can rank/tier them. `plain=True` (tiered mode) always lands `.log` and lets - retier decide compression; otherwise `.gz` is appended when `compress`. same-second - collisions are disambiguated with a counter, checking both .log and .log.gz forms. + ignores the stdlib handler's own rolled name (`.N` for size, `.log.` for + daily) in favor of a uniform timestamped name so all modes converge on one shape + retier can rank/tier. `plain=True` (tiered mode) always lands `.log`, letting retier + decide compression; same-second collisions disambiguate with a counter, checking + both .log and .log.gz forms. """ def namer(default_name: str) -> str: stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock()) @@ -157,18 +151,16 @@ def make_rotator( """rotator: move (or gzip) the source live file to the destination rolled path legacy mode (default): gzip on roll when `compress`, then prune `log_dir` to - `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. `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. + `backup_count` newest rolled files — the stdlib handler's own retention only scans + the live file's directory, so it never sees files redirected into `log_dir`; pruning + here is what bounds retention for daily/size. FOOTGUN: `backup_count <= 0` means + "keep no rolled history", but `prune()` itself no-ops at `<= 0` (its own sentinel for + "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 - next `keep_compressed` are gzipped, the rest deleted. `compress`/`backup_count` are - ignored in this mode (the tier counts bound retention instead). + file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, next + `keep_compressed` gzipped, rest deleted. `compress`/`backup_count` are ignored. """ tiered = keep_uncompressed is not None or keep_compressed is not None @@ -176,11 +168,10 @@ def make_rotator( if not os.path.exists(source): return if tiered: - # dest carries the namer's .gz suffix in compress mode; strip it so the - # freshly-rolled file lands plain and retier decides its tier. disambiguate a - # dest that already exists (a second same-interval daily roll reuses the same - # dated name) with a counter, checking both .log and .log.gz forms, so the - # earlier roll isn't clobbered. + # dest carries the namer's .gz suffix in compress mode; strip it so the roll + # lands plain and retier decides its tier. disambiguate a dest that already + # exists (a second same-interval daily roll reuses the same dated name) with + # a counter, checking both .log and .log.gz forms. plain_dest = _free_dest(dest[:-3] if dest.endswith(".gz") else dest) _move(source, plain_dest) if log_dir is not None and prune_stem is not None: @@ -191,9 +182,6 @@ def make_rotator( else: _move(source, dest) 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: @@ -210,17 +198,16 @@ def rotate_on_start( ) -> None: """move an existing live file into log_dir with a timestamp, gzipped if asked - the rolled file is named off `history_stem` (the project namespace) when given, so - historic files carry the project name independent of the live file's stem; falls back - to the live file's own stem when history_stem is None/empty. + named off `history_stem` (the project namespace) when given, so historic files + carry the project name independent of the live file's stem; falls back to the live + file's own stem when history_stem is None/empty. no-op if the live file doesn't exist. used by rotate="on_start" before the fresh - handler opens a new live file. the timestamp form is run.<%Y-%m-%d_%H-%M-%S>.log. + handler opens a new live file. timestamp form is run.<%Y-%m-%d_%H-%M-%S>.log. - tiered mode (when `keep_uncompressed`/`keep_compressed` are given): the rolled file - always lands PLAIN (so it can occupy the newest uncompressed tier) and `retier` - decides compression/deletion across the whole stem — `compress` is ignored for the - just-rolled file. + tiered mode (`keep_uncompressed`/`keep_compressed` given): the rolled file always + lands PLAIN (so it can occupy the newest uncompressed tier) and `retier` decides + compression/deletion across the whole stem — `compress` is ignored here. """ if not os.path.exists(live_path): return @@ -229,13 +216,12 @@ def rotate_on_start( stem = os.path.basename(history_stem) if history_stem else live_stem stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock()) suffix = ".log.gz" if (compress and not tiered) else ".log" - # the stamp is 1-second resolution; two starts in the same second would collide - # and the second clobber the first. disambiguate with a numeric counter so a rapid - # crash-restart loop doesn't lose the earlier rolled file. check BOTH the .log and - # .log.gz forms of each candidate: in tiered mode an earlier same-stamp roll may have - # already been compressed to .log.gz, and reusing its bare stem would create a second - # file for the same logical roll and break the tier counts + # the 1-second stamp resolution means two starts in the same second collide; + # disambiguate with a counter so a rapid crash-restart loop doesn't lose the + # earlier roll. check BOTH .log and .log.gz forms: in tiered mode an earlier + # same-stamp roll may already be compressed, and reusing its bare stem would + # create a second file for the same logical roll and break the tier counts def _taken(path: str) -> bool: base = path[:-3] if path.endswith(".gz") else path return os.path.exists(base) or os.path.exists(base + ".gz") @@ -257,19 +243,18 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int """re-tier rolled files for stem: newest plain, next gzipped, rest deleted newest-first by mtime: the first `keep_uncompressed` stay uncompressed, the next - `keep_compressed` are gzipped in place (a still-plain file in that band is compressed - to .gz and the plain source removed), and everything beyond + `keep_compressed` are gzipped in place, everything beyond keep_uncompressed+keep_compressed is deleted. the live .log is never touched. fail-soft per file (skip on OSError) so retention never crashes setup. - `stem` is reduced to its basename: rolled files land in log_dir under the basename - (the namer/rotate_on_start basename them), so a `name` containing a directory (e.g. - "sub/run") must be matched by "run." here or nothing matches and retention silently - never fires (unbounded pileup). + FOOTGUN: `stem` is reduced to its basename to match how rolled files land in + log_dir (namer/rotate_on_start basename them) — a `name` containing a directory + (e.g. "sub/run") must be matched by "run." here or nothing matches and retention + silently never fires (unbounded pileup). - ordering is by mtime, then by the roll counter parsed from the name so a same-second - burst (tied mtimes, counter-disambiguated stamps like run..log / run..1.log) - still tiers newest-first correctly rather than falling back to arbitrary listdir order. + ordering is by mtime, then by the roll counter parsed from the name, so a + same-second burst (tied mtimes, counter-disambiguated stamps like run..log / + run..1.log) still tiers newest-first rather than falling back to listdir order. """ stem = os.path.basename(stem) try: @@ -280,13 +265,11 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int except OSError: return 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 — 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. + # dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove + # can leave .log beside .log.gz) so the phantom twin never occupies a + # retention slot and evicts a distinct older roll — but ONLY once the .gz is + # verified to decompress cleanly (_gz_intact): a pre-existing corrupt .gz must never + # win over an intact plain copy, which would delete the only good copy. present = set(entries) kept = [] for p in entries: @@ -297,13 +280,11 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int 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) + # .gz twin is corrupt — keep the intact plain untouched; a later retier + # retries the compress once it's 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 - # (a later same-second roll) is newer + # newest-first: higher mtime first, tied second broken by higher roll counter (later) files.sort(key=lambda t: (t[1], t[2]), reverse=True) keep = keep_uncompressed + keep_compressed @@ -316,11 +297,9 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int elif index >= keep_uncompressed and not path.endswith(".gz"): dest = path + ".gz" if os.path.exists(dest): - # 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, but ONLY once the .gz is verified intact (see _gz_intact): - # a corrupt/truncated .gz here must never win over the last good copy. + # a crash between _gzip_file's write and its os.remove can leave a plain + # source beside a fresh .gz — drop the redundant plain twin, but ONLY + # once the .gz is verified intact (a corrupt .gz must never win) if _gz_intact(dest): try: os.remove(path) @@ -328,8 +307,7 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int 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) + # (atomic write replaces it only once a valid archive exists) try: _gzip_file(path, dest) except OSError: @@ -358,13 +336,13 @@ 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 (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. + matches files beginning with `.` (e.g. run.*), sorted newest-first by mtime + then roll counter (mirrors retier's ordering — 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 - files pile up forever). + FOOTGUN: `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 files pile up forever. """ if backup_count <= 0: return @@ -378,8 +356,6 @@ def prune(log_dir: str, stem: str, backup_count: int) -> None: except OSError: return 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: @@ -406,14 +382,14 @@ def attach_rolling( rolled files are named off `prune_stem` (the HISTORY stem — the project namespace), independent of the live file name, via make_history_namer: `..log[.gz]` - uniform across size and daily. this replaces the stdlib handler's own rolled-name - scheme (`.N` for size, `.log.` for daily), which can't inject a project stem and - (for size) can't be managed once files are redirected into log_dir. + uniform across size and daily — replacing the stdlib handler's own rolled-name + scheme (`.N` for size, `.log.` for daily), which can't inject a project stem + and (for size) can't be managed once files are redirected into log_dir. - pass `prune_stem`/`backup_count` so the rotator prunes `log_dir` after each roll (the - handler's own retention can't see the redirected rolled files). pass - `keep_uncompressed`/`keep_compressed` for tiered retention (newest plain, next gzipped, - rest deleted) — see make_rotator. `tiered=True` lands rolls plain (retier compresses). + pass `prune_stem`/`backup_count` so the rotator prunes `log_dir` after each roll + (the handler's own retention can't see the redirected files). pass + `keep_uncompressed`/`keep_compressed` for tiered retention instead (see + make_rotator); `tiered=True` lands rolls plain (retier compresses). """ namer = make_history_namer( os.path.basename(prune_stem or ""), log_dir, compress, plain=tiered, diff --git a/src/log_setup/setup.py b/src/log_setup/setup.py index dc2d0ef..874d9b1 100644 --- a/src/log_setup/setup.py +++ b/src/log_setup/setup.py @@ -2,14 +2,14 @@ `setup_logging` configures the root logger once for the whole process: a live run.log at a stable path, rotation (daily/size/on_start/none) into a logs/ dir, gzip -of rolled files, retention, console output, and a consistent format. it is called by -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 +of rolled files, retention, console output, and a consistent format. called by the +APPLICATION, not by reusable libraries (those stay emit-only). 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). +of `backup_count`, including `backup_count=0` (means "keep zero rolled files", not +"never roll" — each roll is deleted right after landing). """ import atexit @@ -17,6 +17,8 @@ import logging import logging.handlers import os import queue as _queue +import sys +import traceback from typing import Dict, Optional, Union from .formats import build_formatter @@ -29,6 +31,26 @@ _listener = None _atexit_registered = False +def _exc_text() -> str: + """render sys.exc_info() as text, for capturing a traceback into a buffered warning + + (log.warning(..., exc_info=True) only works logged live from the except block; setup + warnings are deferred, see _flush_warnings, so render eagerly instead) + """ + return "".join(traceback.format_exception(*sys.exc_info())).strip() + + +def _flush_warnings(warnings: list) -> None: + """emit buffered setup-time warnings now that handlers are attached + + setup-time warnings fire before this call's handlers exist, so logging them + immediately would only reach stderr (logging's lastResort) and never the file being + configured — buffer, then flush once attached so they land like any other record + """ + for message, *args in warnings: + log.warning(message, *args) + + def _level_value(level: Union[int, str]) -> int: """coerce a level name or int to a logging level int (defaults to INFO)""" if isinstance(level, bool): @@ -48,9 +70,8 @@ def _level_value(level: Union[int, str]) -> int: def _strict_level_value(level: Union[int, str]) -> Optional[int]: """coerce a level name or int to a logging level int, or None if invalid - unlike `_level_value` (which falls back to INFO for the root `level`), this reports - an invalid value as None so the per-module path can skip + warn rather than silently - apply INFO to a logger the caller named with a typo'd level + unlike `_level_value` (falls back to INFO for the root `level`), reports invalid as + None so the per-module path can skip + warn instead of silently applying INFO """ if isinstance(level, bool): return None @@ -62,37 +83,40 @@ def _strict_level_value(level: Union[int, str]) -> Optional[int]: return resolved if isinstance(resolved, int) else None -def _apply_module_levels(module_levels: Optional[Dict[str, Union[int, str]]]) -> None: +def _apply_module_levels(module_levels: Optional[Dict[str, Union[int, str]]], warnings: list) -> None: """set per-logger level overrides by exact logger name, never crashing - each name->level entry calls `logging.getLogger(name).setLevel()`. names are - matched exactly (no discovery); stdlib hierarchy still applies, so a parent name - quiets its whole subtree. a bad level for one entry is skipped with a warning so the - other entries and the rest of setup still proceed. + names match exactly (no discovery); stdlib hierarchy still applies, so a parent name + quiets its whole subtree. a bad level is skipped, its warning appended to `warnings` + (no handlers exist yet — see _flush_warnings) rather than emitted directly """ if not module_levels: return for mod_name, raw_level in module_levels.items(): value = _strict_level_value(raw_level) if value is None: - log.warning("log_setup: invalid level %r for logger %r; skipping", raw_level, mod_name) + warnings.append(("log_setup: invalid level %r for logger %r; skipping", raw_level, mod_name)) continue logging.getLogger(mod_name).setLevel(value) -def _clear_owned(root: logging.Logger) -> None: - """remove only the handlers this lib previously added; leave app handlers alone""" +def _clear_owned(root: logging.Logger, warnings: list) -> None: + """remove only the handlers this lib previously added; leave app handlers alone + + close failures are appended to `warnings`, not logged directly — no handlers exist + yet at this point in setup (see _flush_warnings) + """ global _listener if _listener is not None: _listener.stop() - # the listener owns the real file/console handlers (only the QueueHandler is - # root-attached + marked); stopping it doesn't close them, so close them here - # to avoid relying on GC finalizers across a re-setup + # listener owns the real file/console handlers (only QueueHandler is root- + # attached + marked); stopping it doesn't close them, so close here rather than + # rely on GC finalizers across a re-setup for wrapped in getattr(_listener, "handlers", ()): try: wrapped.close() except Exception: - log.warning("log_setup: failed to close queued handler %r", wrapped, exc_info=True) + warnings.append(("log_setup: failed to close queued handler %r: %s", wrapped, _exc_text())) _listener = None for handler in list(root.handlers): if getattr(handler, _MARKER, False): @@ -100,9 +124,9 @@ def _clear_owned(root: logging.Logger) -> None: try: handler.close() except Exception: - # a handler failing to close must not abort re-setup, but log it - # rather than swallow silently (consistent with the lib's warn pattern) - log.warning("log_setup: failed to close handler %r during re-setup", handler, exc_info=True) + warnings.append( + ("log_setup: failed to close handler %r during re-setup: %s", handler, _exc_text()) + ) def _tag(handler: logging.Handler) -> logging.Handler: @@ -140,25 +164,25 @@ def _history_stem() -> str: def _file_handler( name: str, history_stem: str, live_path: str, log_dir: str, rotate: Optional[str], backup_count: int, max_bytes: int, compress: bool, - keep_uncompressed: Optional[int], keep_compressed: Optional[int], + keep_uncompressed: Optional[int], keep_compressed: Optional[int], warnings: list, ) -> logging.Handler: """build the configured file handler with custom rolling into log_dir `name` is the LIVE stem (drives live_path); `history_stem` is the PROJECT stem that - rolled/historic files are named off + the retention glob keys on. they are decoupled: - the live file keeps its defined name, historic files carry the project namespace. + rolled/historic files are named off + the retention glob keys on — decoupled: the + live file keeps its defined name, historic files carry the project namespace. an + unknown `rotate` is appended to `warnings` rather than logged directly (see + _flush_warnings — no handlers exist yet at this point). """ tiered = keep_uncompressed is not None or keep_compressed is not None 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 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). + # stdlib doRollover no-ops at backupCount==0, and its numbered .1/.2 shift can't + # manage files redirected into log_dir — force nonzero so the roll always fires, + # and let attach_rolling's namer + retier/prune bound retention instead. the + # REAL backup_count (maybe 0) still flows to attach_rolling below: make_rotator + # treats <=0 there as "keep no rolled history" and deletes each roll right after + # landing, rather than passing 0 to prune() (whose own <=0 is a "leave history + # alone" no-op — that mismatch is 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", @@ -188,13 +212,12 @@ def _file_handler( rotate_on_start(live_path, log_dir, compress, history_stem=history_stem) prune(log_dir, history_stem, backup_count) elif rotate is not None: - # a typo'd rotate value (e.g. "hourly") would otherwise silently fall through - # to a non-rotating FileHandler and grow forever — warn, matching the - # unknown-`output` convention, rather than degrade silently - log.warning( + # a typo'd value (e.g. "hourly") would otherwise silently fall through to a + # non-rotating FileHandler and grow forever — warn instead of degrade silently + warnings.append(( "log_setup: unknown rotate %r; expected 'daily'/'size'/'on_start'/None — " "no rotation applied (single growing file)", rotate, - ) + )) handler = logging.FileHandler(live_path, encoding="utf-8") return handler @@ -220,58 +243,61 @@ def setup_logging( """configure the root logger for the whole process and return it `name` -> .log live file at cwd; rolled/compressed copies go to `log_dir`. a - trailing ".log" in `name` is stripped so "latest" and "latest.log" both produce the - live file latest.log (never latest.log.log). + trailing ".log" in `name` is stripped so "latest" and "latest.log" both produce + latest.log (never latest.log.log). + `history_name` names the rolled/historic files (`..log[.gz]`), - independent of the live file: it defaults to the PROJECT namespace = the cwd basename - (run from bestbuy/ -> historic files bestbuy....), and can be set explicitly. the - live file always keeps `name`; only the historic files carry the project name. + independent of the live file: defaults to the PROJECT namespace = the cwd basename + (run from bestbuy/ -> historic files bestbuy....), settable explicitly. the + live file always keeps `name`; only historic files carry the project name. + `keep_uncompressed`/`keep_compressed` (default None) enable TIERED retention: when either is given, rolled files are kept as the newest `keep_uncompressed` uncompressed - + the next `keep_compressed` gzipped, and the rest are deleted (total retained = - sum). this applies to "on_start", "daily", and "size". `backup_count` and the - gzip-on-roll behavior of `compress` are IGNORED in tiered mode (the tier counts bound - retention). pass NEITHER knob and rotation behaves exactly as before (backup_count + - compress) — existing callers are unaffected. + + the next `keep_compressed` gzipped, rest deleted (total retained = sum). applies to + "on_start", "daily", and "size". `backup_count` and gzip-on-roll `compress` are + IGNORED in tiered mode. pass NEITHER knob and rotation behaves exactly as before. + `level` is the root default every logger inherits. `module_levels` is an optional - map of exact logger name -> level applied after the root is set, the ergonomic way - to quiet noisy dependencies (e.g. {"motor": "WARNING", "aiohttp": "WARNING"}) from - the one setup call instead of scattering `getLogger(...).setLevel(...)` afterwards — - it's stdlib hierarchy under the hood, not new capability. names match EXACTLY (no - discovery: a typo'd name silently configures an unused logger), but stdlib hierarchy - 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. + map of exact logger name -> level applied after the root is set — the ergonomic way + to quiet noisy dependencies (e.g. {"motor": "WARNING"}) from the one setup call + instead of scattering `getLogger(...).setLevel(...)` afterwards (stdlib hierarchy + under the hood, not new capability). names match EXACTLY (no discovery: a typo'd + name silently configures an unused logger), but hierarchy applies, so naming a + parent ("aiohttp") quiets its whole subtree. str or int per entry; a bad value is + skipped with a warning and never aborts the others or the setup. + `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 | - message`, local time) or "json" (structured one-JSON-object-per-line for the - Grafana/Loki path, UTC timestamps, `extra=` fields surfaced as top-level keys); both - file and console use the chosen format and the live-file name is the same regardless. - the raw `fmt`/`datefmt` overrides apply to text output only. idempotent: a repeat call - clears only the handlers this function added. never raises over logging — an - unwritable `log_dir` falls back to console-only with a warning even when `console` is - off, so output is never silently lost; an unknown `output` falls back to text. + "disable rotation". `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 (stopped at exit). `output` is "text" (default, human `time | + module | level | message`, local time) or "json" (structured JSON Lines for the + Grafana/Loki path, UTC timestamps + a unix-epoch `ts`, `extra=` fields surfaced as + top-level keys); file and console use the same format, live-file name unaffected. + `fmt`/`datefmt` apply to text output only. + + idempotent: a repeat call clears only the handlers this function added. never + raises over logging — an unwritable `log_dir` falls back to console-only with a + warning even when `console` is off; an unknown `output` falls back to text. """ global _listener, _atexit_registered + warnings: list = [] + root = logging.getLogger() root.setLevel(_level_value(level)) - _apply_module_levels(module_levels) - _clear_owned(root) + _apply_module_levels(module_levels, warnings) + _clear_owned(root, warnings) formatter = build_formatter(output, fmt, datefmt) stem = _normalize_name(name) live_path = f"{stem}.log" - # historic/rolled files are named off the project namespace, independent of the live - # file: history_name if given, else the cwd basename (e.g. run from bestbuy/ -> historic - # files bestbuy..log[.gz]). normalized + basenamed like `name`; falls back to the - # live stem for a degenerate cwd so naming/retention never break. + # historic/rolled files are named off the project namespace: history_name if given, + # else the cwd basename. normalized + basenamed like `name`; falls back to the live + # stem for a degenerate cwd so naming/retention never break. history_source = history_name if history_name is not None else _history_stem() history_stem = os.path.basename(_normalize_name(history_source)) or stem @@ -287,7 +313,7 @@ def setup_logging( try: fh = _file_handler( stem, history_stem, live_path, log_dir, rotate, backup_count, max_bytes, compress, - keep_uncompressed, keep_compressed, + keep_uncompressed, keep_compressed, warnings, ) fh.setFormatter(formatter) handlers.append(fh) @@ -306,8 +332,8 @@ def setup_logging( _listener = logging.handlers.QueueListener(record_queue, *handlers, respect_handler_level=True) _listener.start() if not _atexit_registered: - # register once — atexit doesn't dedupe, so repeated queue re-setups would - # otherwise stack identical callbacks (harmless but unbounded) + # register once — atexit doesn't dedupe; repeated re-setups would otherwise + # stack identical callbacks atexit.register(_stop_listener) _atexit_registered = True else: @@ -315,7 +341,11 @@ def setup_logging( root.addHandler(_tag(handler)) if not file_ok: - log.warning("log_setup: log_dir %r not writable; logging to console only", log_dir) + warnings.append(("log_setup: log_dir %r not writable; logging to console only", log_dir)) + + # flush now that handlers are attached, so setup-time warnings actually land in the + # configured log rather than being lost to stderr before any handler existed + _flush_warnings(warnings) return root