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 <dev@disqualifier.me>

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.<t1>.log   latest.<t2>.log   latest.<t3>.log       <- 3 newest: plain
-latest.<t4>.log.gz ... latest.<t10>.log.gz                 <- next 7: gzipped
-(anything past 10 deleted)
+./latest.log                                              <- live (stable, tail -f, in cwd)
+logs/
+    bestbuy.<t1>.log  bestbuy.<t2>.log  bestbuy.<t3>.log   <- 3 newest: plain
+    bestbuy.<t4>.log.gz ... bestbuy.<t10>.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
 

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 = []

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"

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(),

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 `<stem>.<Y-m-d_H-M-S>.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.<date>` 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.<date>` 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 <name>.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 <stem>.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.<t>.log / run.<t>.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.<t>.log /
+    run.<t>.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 <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 — 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 <x>.log beside <x>.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 `<stem>.` (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 `<stem>.` (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: `<stem>.<stamp>.log[.gz]`
-    uniform across size and daily. this replaces the stdlib handler's own rolled-name
-    scheme (`.N` for size, `.log.<date>` 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.<date>` 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,

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(<level>)`. 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` -> <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 (`<history_name>.<timestamp>.log[.gz]`),
-    independent of the live file: it defaults to the PROJECT namespace = the cwd basename
-    (run from bestbuy/ -> historic files bestbuy.<stamp>...), 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.<stamp>...), 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.<stamp>.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