28 Commits
Author SHA1 Message Date
dsql 481d076dd2 release: 1.0.0
first stable release. pre-1.0.0 verification complete: all surviving MED regressions and
gaps resolved and independently re-fired, tree audited clean across the suite.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 21:21:00 -04:00
dsql 3dd3a8842c fix: thread live_stem into rotate_on_start's tiered retier call
the tiered on_start path called retier without live_stem, so on a project whose history
stem differs from the live stem (history_name set), legacy live-named rolls (run.<stamp>.log)
never matched _is_rolled_name and accumulated forever - every OTHER retier/prune call site
(make_rotator, attach_rolling) already threaded live_stem, this one was missed. pass it
through like the others; retier dedupes the live_stem==stem case, so the default path is
unchanged and a foreign same-dir file is still spared.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 21:03:46 -04:00
dsql cb8acac76f fix: prune/retier recognize legacy rolls named off the live name; correct gzip docs
Legacy pre-v0.5.0 daily rolls were named off the LIVE file name (run.log.<date>), but
prune/retier only matched the history stem (the cwd basename), so in the default upgrade
path an existing legacy backlog was never recognized and piled up forever. prune/retier/
make_rotator/attach_rolling now thread the live name as an optional live_stem so both shapes
are pruned; a foreign same-stem file is still left alone (all forms stay date-bearing).
README + CLAUDE.md corrected to describe the atomic compress-or-skip behavior (40310b8 removed
the runtime _gz_intact reconciliation the docs still claimed).

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 19:35:53 -04:00
dsql 3f3a797fde fix: prune/retier recognize legacy pre-v0.5.0 daily rolls; remove dead make_namer
_is_rolled_name only matched the current uniform namer shape, so an upgraded deployment's
existing pre-v0.5.0 daily rolls (<stem>.log.<Y-m-d>[.gz], the stdlib TimedRotatingFileHandler
shape) were classified foreign and never pruned - piling up forever. the pattern now also
matches that legacy shape (still date-bearing, so a foreign <stem>.audit.log is untouched).
also drops make_namer, which had zero callers since attach_rolling moved to make_history_namer.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 17:19:38 -04:00
dsql 40310b8cb6 refactor: make compression atomic-or-skip, delete the corrupt-gz reconciliation
_gzip_file now verifies the tmp .gz decompresses BEFORE it os.replaces onto the final path
and removes the plain, so a crash/OOM/failed-verify at any point leaves the plain .log intact
and no .gz - a corrupt/partial .gz is never produced. with that guarantee, the plain-vs-corrupt-gz
reconciliation is dead code: retier's dedupe now drops a plain twin unconditionally (the .gz is
always intact), and both _gz_intact/corrupt-twin guards (the beyond-keep skip added in 4ad066c and
the compression-tier fall-through) are removed. this eliminates the whole 'intact plain vs corrupt
gz twin' class - including the newly-found compression-tier data-loss path - at the source. verified:
killed-mid-gzip leaves the .log intact with no .gz; a successful roll leaves only a decompressible
.gz; no path deletes an intact plain; normal retention still prunes.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 17:02:20 -04:00
dsql 4ad066ca5c fix: retier never deletes an intact plain roll in favor of a corrupt .gz twin
the beyond-keep delete branch had no _gz_intact guard: when an intact plain file and its
CORRUPT .gz twin (same mtime) straddled the keep boundary and listdir yielded the .gz first,
the .gz sorted into the kept range while the intact plain sorted past it and was deleted -
leaving the corrupt archive as the sole copy (permanent data loss), violating the 'corrupt
.gz never wins over intact plain' invariant the two dedupe sites already enforce. the delete
now skips an intact plain whose only surviving twin is a corrupt .gz; a later retier retires
it once a clean .gz exists. reproduced with a forced .gz-first listdir: old deleted the plain,
new keeps it.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 16:46:51 -04:00
dsql f8d3322591 fix: drop _file_handler's unused name parameter
leftover from the v0.5.0 history-namespace split - every path inside
_file_handler already uses live_path/history_stem/log_dir, never name. the
docstring still explained it as "the LIVE stem" though nothing read it.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 00:15:10 -04:00
dsql ca9bf4520b fix: build_formatter routes the unknown-output warning through the setup buffer
build_formatter warned immediately via getLogger(__name__).warning, but
setup_logging calls it after _clear_owned strips the lib's handlers and before
any new handler attaches - so the warning hit a handler-less root and landed
on stderr via lastResort, never reaching the configured log. The v0.6.0
warnings buffer already threads this class of setup-time warning through for
an unknown rotate value; build_formatter now takes the same warnings list and
appends to it instead of emitting inline, so setup_logging can flush it once
handlers are attached like the others.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 00:14:54 -04:00
dsql 3454f73b6a fix: prune/retier no longer treat a foreign same-stem file as a rolled log
prune() and retier() matched any file starting with "<stem>." (minus the live
<stem>.log), with no check that the name actually has this lib's own rolled
shape (<stem>.<stamp>[.N].log[.gz]). Since v0.5.0 the default history_stem is
the cwd basename, so a project dropping its own same-stem file into log_dir
(e.g. proj.audit.log, proj.stats.json) got silently deleted by prune once it
aged past backup_count, or folded into retier's tier accounting (gzipped or
deleted as if it were a real roll). Candidates are now filtered through
_is_rolled_name before being treated as a roll.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 00:14:20 -04:00
dsql a6edb965d0 fix: queue=True no longer strips exc_info before JsonLinesFormatter sees it
QueueHandler.prepare() formatted the record with its own default formatter and
nulled exc_info/exc_text/stack_info before the listener's real formatter ran,
so queue=True + output="json" produced a JSON line with no exc_info key and
the traceback folded into message instead. _PreservingQueueHandler skips that
premature format-and-strip (safe here - the queue is in-process only, nothing
needs to stay picklable) so the listener's handler formats the untouched
record exactly once, matching the non-queued path.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-06 00:14:07 -04:00
dsql e12a978a2b refactor: derive __version__ from package metadata (single source)
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-03 16:59:26 -04:00
dsql 17d1d20865 fix: console handler writes to stdout, not stderr
console=True now binds sys.stdout explicitly (was the stdlib StreamHandler
stderr default), so a supervisor capturing stdout sees console log lines.
console stays off by default (file is the primary sink). docs corrected to
stdout.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-03 16:31:51 -04:00
dsql 6fb245f690 docs: fix console=True stream claim, stdout -> stderr (StreamHandler default)
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-03 16:23:22 -04:00
dsql e78a384f1a fix: rotate-mode-aware zero-retention delete in make_rotator (logsetup-1)
v0.5.1's rotate="size" fix added an unconditional os.remove(dest) at
backup_count<=0 in make_rotator to bound the live file, but the rotator is
shared with rotate="daily" and had no mode awareness - every midnight roll
under daily with backup_count=0 was deleting the just-rolled log instead of
leaving it unpruned. make_rotator/attach_rolling now take rotate_mode and
gate the delete-on-land branch to "size" only, matching the documented
contract that only size always bounds the live file. Bump 0.6.1 -> 0.6.2.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-03 16:15:03 -04:00
dsql 4d1acc3a47 docs: compress prose/module docstrings, em-dash->hyphen (de-bloat wave 1)
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-03 00:32:56 -04:00
dsql 93994da9d6 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>
2026-07-02 23:30:01 -04:00
dsql 8bf1866ca2 fix: gzip crash-safety + size rotation always bounds live file (logsetup-7/8/9)
_gzip_file now writes to a .tmp sibling and atomically os.replaces it onto
the final .gz path, so a crash/OOM mid-write can never leave a truncated
.gz where retention trusts it; retier's plain/gz dedupe additionally
verifies a .gz decompresses cleanly before removing its plain twin, so a
corrupt .gz is never preferred over the last intact copy.

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

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

Bumps to v0.5.1.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-02 17:24:26 -04:00
dsql 1207c53742 feat: historic logs named off the project namespace (cwd basename / history_name)
the live file keeps its defined name (latest.log); rolled/historic files are now named off
the PROJECT namespace so you can tell which service a log came from at a glance. default =
os.path.basename(os.getcwd()) (run from bestbuy/ -> historic bestbuy.<stamp>.log[.gz]);
override with the new history_name= param.

- decouple the rolled stem (history) from the live stem (name) in setup.py; thread
  history_stem into BOTH the namers AND prune/retier (same stem, or retention breaks).
- unify size + daily on make_history_namer -> <stem>.<stamp>.log[.gz] (was stdlib .N /
  .log.<date>); rotate_on_start takes history_stem.

behavior-visible: rolled names differ from pre-0.5.0 (were the live stem). pass
history_name=name for the old naming. execute-verified across on_start/daily/size (tiered +
non-tiered), default-cwd + explicit + history==name + normalization edges; v0.4.x fixes
(rotation/tiering/retention) all still hold. bump v0.4.3 -> v0.5.0

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-01 01:58:10 -04:00
dsql b52c1d37fa fix: LOW/nit clearance — retier twin dedupe + same-second counter ordering, warn on unknown rotate
- logsetup-2: retier drops a plain file whose .gz twin exists (crash-between-write-and-remove
  residue) up front, so the phantom twin never occupies a retention slot / evicts a real roll.
- logsetup-5: retier breaks mtime ties by the roll counter parsed from the name, so a
  same-second on_start burst tiers newest-first instead of arbitrary listdir order.
- logsetup-3: tiered daily rotator disambiguates an existing dated dest with a counter (no
  clobber on a second same-interval roll).
- logsetup-6: unknown rotate value warns (matching the unknown-output convention) instead of
  silently degrading to a non-rotating file.
- README: size-mode backup naming clarified (numbered flat vs timestamped tiered).
verified stdlib-only; v0.4.0/v0.4.1/size suites still pass. bump v0.4.2 -> v0.4.3

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-07-01 00:28:18 -04:00
dsql 6a10f3acc0 fix: tiered rotate='size' actually rotates and tiers (logsetup-1, logsetup-4)
tiered size mode was broken two ways: (1) stdlib RotatingFileHandler's numbered .1/.2 shift
can't manage files redirected into log_dir, so every roll overwrote slot 1 -> ~99% of
history silently lost; (2) doRollover is gated on backupCount>0, so backup_count=0 (which
the docstring says is ignored in tiered mode) meant NO rotation + unbounded live file.

fix: tiered size now uses a timestamped per-roll namer (make_size_namer) like daily/on_start
so retier manages the pile, and forces a nonzero internal backupCount so the roll always
fires (retier bounds retention, not backupCount). non-tiered size unchanged.

verified: tiered size rotates + bounds to tier total (was stuck at 1); backup_count=0 rotates
+ live file bounded (was unbounded); legacy size back-compat intact; v0.4.0/v0.4.1 suites
still pass. bump v0.4.1 -> v0.4.2

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-30 21:04:58 -04:00
dsql ece9a6b9ca fix: retention dead when name contains a directory (basename the stem)
rolled files land in log_dir under their basename (the namer/rotate_on_start basename
them), but prune()/retier() globbed the un-basenamed name. a name like 'sub/run' matched
nothing, so old .log/.gz files piled up forever (slow disk leak; the live file was fine).
basename the stem at the top of both prune() and retier(). regression-verified with
name='sub/run' (10 retained vs 12/dead before). bump v0.4.0 -> v0.4.1

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-30 03:49:35 -04:00
dsql 595f0363b3 feat: tiered restart/retention (keep_uncompressed/keep_compressed) + name normalize
- keep_uncompressed/keep_compressed: newest N rolled logs plain, next M gzipped, rest
  deleted. applies to on_start/daily/size. opt-in by knob presence; without them the
  legacy backup_count + gzip-on-roll path is unchanged (existing consumers unaffected).
- _normalize_name: 'latest' and 'latest.log' both -> live latest.log (no .log.log).
- _gzip_file preserves source mtime (stable tier ordering across re-tiers).
- rotate_on_start collision counter checks both .log and .log.gz (no duplicate logical
  roll when a same-stamp file was already compressed).

execute-verified stdlib-only incl. a back-compat control proving the no-knobs path is
unchanged. bump v0.3.2 -> v0.4.0

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-30 03:13:43 -04:00
dsql efb35195f1 chore: ignore .claude/ dir (CLAUDE.md now lives under .claude/)
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 21:55:13 -04:00
dsql fc0898d70e fix: LS-1 close queued handlers on re-setup; LS-2 register atexit once
LS-1: re-setup closes the QueueListener's wrapped file/console handlers after stopping it
(was: relied on GC). LS-2: atexit registration guarded by a module flag so repeated
queue=True re-setups don't stack callbacks. JSON formatter caches the rendered traceback on
the record (no per-handler re-render); _move dest precondition documented.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 21:35:21 -04:00
dsql 011588a712 docs: pin install line to release, note unpinned-latest option
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 18:13:55 -04:00
dsql ddc81dd8fe docs: show unpinned install line; note tag-pinning for reproducibility
Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 18:07:40 -04:00
dsql 74c5a42c5a fix: cross-filesystem roll fallback; on_start collision; small nits (v0.3.2)
- the non-compress rotator and on_start move fall back to shutil.move when os.replace
  hits OSError(EXDEV) across filesystems, so rolls land on a separate logs volume /
  container bind-mount instead of failing every rotation via the handler's silent
  handleError (L18)
- on_start disambiguates a same-second restart with a numeric counter so a rapid
  crash-restart loop doesn't clobber the earlier rolled file (L17)
- reject a bool root level (True==1) consistently with the per-module path; alias the
  queue module import to drop the queue:bool param shadow; log (not swallow) a
  handler.close failure during re-setup (nits).

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 17:58:26 -04:00
dsql ff29e05322 fix: JSON extra cannot clobber canonical time/level/module fields (v0.3.1)
guard the extra-merge loop with the formatter's own output keys (time/level/module/
message). stdlib LogRecord rejects extra keys colliding with real attribute names, but
time/level are NOT LogRecord attrs, so a caller's extra={"time":...}/{"level":...}
previously overwrote the UTC timestamp / levelname — the two fields Loki/Grafana alert
on. now those keys are reserved and a colliding extra is dropped.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 17:11:45 -04:00
7 changed files with 704 additions and 154 deletions
+1 -1
View File
@@ -1,5 +1,5 @@
# claude # claude
CLAUDE.md .claude/
# python # python
__pycache__/ __pycache__/
+130 -15
View File
@@ -13,11 +13,13 @@ and emit; their records flow into the handlers `log_setup` wired.
## Install ## Install
``` ```
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.3.0 log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.3
``` ```
No dependencies — stdlib only. No dependencies — stdlib only.
Drop the `@v0.6.3` suffix from the line above to install the latest unpinned.
## Quick start ## Quick start
```python ```python
@@ -41,17 +43,86 @@ emits; the records land in the configured root.
- **Format:** `2026-06-27 19:55:05 | module.name | INFO | message`. `%(name)s` is the - **Format:** `2026-06-27 19:55:05 | module.name | INFO | message`. `%(name)s` is the
`getLogger` name each module used, so you see which lib/module logged. `getLogger` name each module used, so you see which lib/module logged.
- **Rotation** (`rotate=`): - **Rotation** (`rotate=`):
- `"daily"` (default) — rolls at midnight, dated name into `log_dir`, keeps - `"daily"` (default) — rolls at midnight into `log_dir`, keeps `backup_count` days.
`backup_count` days. - `"size"` — rolls at `max_bytes` into `log_dir`, keeps `backup_count`. `backup_count=0`
- `"size"` — rolls at `max_bytes`, numbered backups in `log_dir`. means **keep no rolled history**: the live file still rolls at `max_bytes` (size is
- `"on_start"` — on startup, moves an existing `run.log` into `log_dir` always bounded), each rolled file is deleted immediately after landing — it does not
(`run.<timestamp>.log[.gz]`) and starts fresh; prunes to `backup_count`. disable rotation (see **Retention** below).
- `"on_start"` — on startup, moves an existing live file into `log_dir` and starts fresh;
prunes to `backup_count`.
- `None` — single file, no rotation. - `None` — single file, no rotation.
- **compress=True** (default) gzips each rolled file (`run.log.2026-06-27.gz`). - **Historic files are named off the project** — see below. Every rolled file is
- **Retention** = `backup_count` (default 14) for every mode. `<project>.<timestamp>.log[.gz]`; the live file keeps its own name.
- **compress=True** (default) gzips each rolled file.
- **Retention** = `backup_count` (default 14) for every mode — unless tiered retention is
enabled (below). For `rotate="size"`, `backup_count=0` is "keep none" (not "disable
rotation") — see the `size` bullet above and the note at the bottom of this section.
- **console=True** (off by default) also logs to stdout in the same format — opt in when - **console=True** (off by default) also logs to stdout in the same format — opt in when
you want live terminal output alongside the file. you want live terminal output alongside the file.
The `name` you pass is normalized so it produces exactly one `.log`: `name="latest"` and
`name="latest.log"` both yield the live file `latest.log` (never `latest.log.log`).
## Historic files are named off the project (`history_name`)
The **live** file keeps its defined `name` (`latest.log`). The **historic** (rolled/gz)
files are named off the **project namespace** — by default the current directory's basename
— so you can tell at a glance which service a log came from:
```python
# app run from bestbuy/run.py , with name="latest":
setup_logging(name="latest", rotate="daily")
# logs/
# latest.log <- live (the tail -f target)
# bestbuy.2026-07-01_02-00-00.log <- historic, named off the project dir
# bestbuy.2026-06-30_02-00-00.log.gz
```
- **Default** = `os.path.basename(os.getcwd())` (the project directory). Zero config.
- Override with **`history_name="foo"`** → historic files become `foo.<timestamp>.log[.gz]`.
- This changed in **v0.5.0**: historic files used to reuse the live `name`. To keep the old
behavior, pass `history_name=name`.
- Retention (tier counts / `backup_count`) is unchanged — it's just keyed to the project
stem now.
## Tiered retention (`keep_uncompressed` / `keep_compressed`)
The default is a flat `backup_count`: every rolled file is gzipped on roll and the oldest
are deleted past the count. If instead you want the recent logs **uncompressed** (read them
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
keep_uncompressed=3, # newest 3 rolled logs kept PLAIN
keep_compressed=7, # next 7 kept GZIPPED; total retained = 10
)
```
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 (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`,
then re-tiers: newest `keep_uncompressed` stay plain, the next `keep_compressed` are
gzipped in place, the rest deleted. Total kept = `keep_uncompressed + keep_compressed`.
- **Opt-in by presence** — pass either knob to enable tiering. Pass **neither** and
rotation behaves exactly as before (`backup_count` + gzip-on-roll), so existing callers
are unaffected.
- In tiered mode `backup_count` and the gzip-on-roll behavior of `compress` are **ignored**
— the tier counts bound retention instead.
- `keep_uncompressed=0` → everything gzipped; `keep_compressed=0` → only the plain tier.
Retention is count-based (not time-based).
## Output format (`output=`) ## Output format (`output=`)
Two formats, two needs. Default is `"text"`; the live-file name is the same either way Two formats, two needs. Default is `"text"`; the live-file name is the same either way
@@ -68,17 +139,22 @@ Promtail glob, bind-mount path, or your `tail` command.
```python ```python
setup_logging(name="run", output="json") setup_logging(name="run", output="json")
logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"}) logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"})
# -> {"time": "2026-06-28T14:03:11Z", "level": "INFO", "module": "bot.core", # -> {"time": "2026-06-28T14:03:11Z", "ts": 1782151391, "level": "INFO",
# "message": "ready", "monitor": "heartbeat"} # "module": "bot.core", "message": "ready", "monitor": "heartbeat"}
``` ```
- **Fields:** `time`, `level`, `module`, `message` always; any `extra={...}` keys land - **Fields:** `time`, `ts`, `level`, `module`, `message` always; any `extra={...}` keys
as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels — the lib land as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels —
stays domain-agnostic); error records carry the traceback in `exc_info` (never dropped). 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 - **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; 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 Grafana converts to local for display. (Text mode stays local — that's a human on one
box.) 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 - 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, builds fields, not a format string). An unknown `output` falls back to text + warns,
never crashes. **Zero new deps** — stdlib `json` only. never crashes. **Zero new deps** — stdlib `json` only.
@@ -92,7 +168,10 @@ setup_logging(
level="INFO", # root level everything inherits (str name or logging constant) level="INFO", # root level everything inherits (str name or logging constant)
module_levels=None, # {logger_name: level} per-logger overrides (exact name match) module_levels=None, # {logger_name: level} per-logger overrides (exact name match)
rotate="daily", # "daily" | "size" | "on_start" | None rotate="daily", # "daily" | "size" | "on_start" | None
backup_count=14, # rotated files to keep (older auto-deleted) history_name=None, # stem for rolled/historic files; None -> cwd basename (project)
backup_count=14, # rotated files to keep (flat retention; ignored if tiered)
keep_uncompressed=None, # tiered: newest N rolled logs kept PLAIN (opt-in)
keep_compressed=None, # tiered: next M rolled logs kept GZIPPED (opt-in)
max_bytes=10_000_000, # only for rotate="size" max_bytes=10_000_000, # only for rotate="size"
compress=True, # gzip rolled files compress=True, # gzip rolled files
console=False, # also log to stdout (off by default; opt in) console=False, # also log to stdout (off by default; opt in)
@@ -161,6 +240,42 @@ setup_logging(name="run", queue=True)
duplicate lines) and leaves handlers your app added itself alone. duplicate lines) and leaves handlers your app added itself alone.
- **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to - **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to
console-only with a warning instead of raising. console-only with a warning instead of raising.
- **`rotate="size"` always bounds the live file (v0.5.1+).** Previously, `backup_count=0`
with `rotate="size"` silently disabled rotation entirely (the live file grew forever,
ignoring `max_bytes`). As of v0.5.1, the live file always rolls at `max_bytes`
regardless of `backup_count`; `backup_count=0` means "keep zero rolled files" (each roll
is deleted right after it lands) rather than "never roll." `backup_count>=1` behaves as
documented (keeps that many rolled files). This does not change `"daily"`/`"on_start"`,
where `backup_count=0` still means "roll, but don't prune the rolled files" (unbounded
`log_dir` growth) — that is a separate, pre-existing knob, not this fix's scope.
- **`console=True` writes to stdout (v0.6.3).** the console handler now binds `sys.stdout`
explicitly instead of the stdlib `StreamHandler` default of `sys.stderr`, so a supervisor
capturing stdout sees console log lines. `console` stays off by default — the file is the
primary sink.
- **`"daily"` regression fixed (v0.6.2).** v0.5.1's `rotate="size"` fix above shared its
rotator with `"daily"`, so a `rotate="daily", backup_count=0` roll was incorrectly
deleted at every midnight rollover instead of just landing unpruned. The rotator is now
rotate-mode aware: the zero-retention delete only ever fires for `"size"`, matching the
contract in the bullet above — `"daily"`/`"on_start"` with `backup_count=0` were always
meant to roll without pruning and now do again.
- **Gzip is atomic compress-or-skip (v0.5.1+).** `_gzip_file` writes to a `.tmp` sibling,
verifies it decompresses cleanly, and only then `os.replace`s it onto the final `.gz` and
removes the plain source — a crash/OOM/interrupt at any point leaves the plain `.log`
intact with no `.gz` (or the `.tmp` cleaned up), so this code never produces a truncated
`.gz` at the path retention trusts. Because a corrupt `.gz` can't arise from this path, the
tiered retention dedupe drops a plain twin unconditionally when its `.gz` exists (no
runtime `_gz_intact` reconciliation — that was removed once compression became atomic).
- **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 ## Scope — what this is NOT
@@ -177,4 +292,4 @@ color formatting, per-logger filters, remote handlers.
## Versioning ## Versioning
Tagged `vX.Y.Z`. Pin the tag. Releases are tagged `vX.Y.Z`. The install line above pins a release; drop the `@vX.Y.Z` suffix to install the latest unpinned. Pin deliberately for reproducible installs.
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project] [project]
name = "log_setup" name = "log_setup"
version = "0.3.0" version = "1.0.0"
description = "stdlib app-entry-point logging setup: live run.log, rotation, gzip, retention, consistent format" description = "stdlib app-entry-point logging setup: live run.log, rotation, gzip, retention, consistent format"
requires-python = ">=3.10" requires-python = ">=3.10"
dependencies = [] dependencies = []
+9 -10
View File
@@ -1,22 +1,21 @@
"""log_setup app-entry-point logging configuration (sync, stdlib only). """log_setup - app-entry-point logging configuration (sync, stdlib only). see README.
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.
from log_setup import setup_logging from log_setup import setup_logging
setup_logging(name="run", level="INFO") # daily rotation, logs/ dir, gzip setup_logging(name="run", level="INFO") # daily rotation, logs/ dir, gzip
log = logging.getLogger(__name__) 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 reusable libraries do NOT call this; the application owns setup, libraries only emit.
emit; the application owns this setup. shipping logs to a backend is out of scope
(that's Promtail's job against the produced files).
""" """
from importlib.metadata import PackageNotFoundError, version
from .setup import setup_logging from .setup import setup_logging
__all__ = ["setup_logging"] __all__ = ["setup_logging"]
__version__ = "0.3.0" try:
__version__ = version("log_setup")
except PackageNotFoundError:
__version__ = "0.0.0+unknown"
+33 -20
View File
@@ -1,10 +1,8 @@
"""log formats for the app-wide setup: human-readable text + structured JSON lines. """log formats for the app-wide setup: human-readable text + structured JSON lines.
two output formats, two proven needs. `text` (default) is the human `tail -f` format `text` (default) is the human `tail -f` format (`time | module | level | message`,
(`time | module | level | message`, local time). `json` is the Grafana/Loki path local time). `json` is the Grafana/Loki path - one JSON object per line, UTC
one JSON object per line (JSON Lines), fields parsed into labels natively, UTC timestamps so logs aggregated from many machines sort unambiguously. see README.
timestamps so logs aggregated from many machines/containers sort unambiguously.
`%(name)s` is the getLogger name the emitting module used, so each module shows.
""" """
import datetime import datetime
@@ -15,33 +13,40 @@ DEFAULT_FORMAT = "%(asctime)s | %(name)s | %(levelname)s | %(message)s"
DEFAULT_DATEFMT = "%Y-%m-%d %H:%M:%S" DEFAULT_DATEFMT = "%Y-%m-%d %H:%M:%S"
_RESERVED = frozenset(vars(logging.makeLogRecord({})).keys()) | {"message", "asctime"} _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`/`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): class JsonLinesFormatter(logging.Formatter):
"""format each record as a single-line JSON object (JSON Lines / .jsonl) """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` emits at minimum time/ts/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 suffix; `ts` is the same instant as a unix epoch int, both sortable across
containers sort unambiguously — Grafana converts to local for display. any machines/containers. any field passed via logging `extra={...}` lands as a
field passed via logging `extra={...}` lands as a top-level JSON field, which top-level JSON field. a traceback (exc_info) is rendered into an `exc_info`
is how a caller stamps monitor/service/request-id for Loki labels without the string field rather than dropped.
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: def format(self, record: logging.LogRecord) -> str:
when = datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc) when = datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc)
payload = { payload = {
"time": when.strftime("%Y-%m-%dT%H:%M:%SZ"), "time": when.strftime("%Y-%m-%dT%H:%M:%SZ"),
"ts": int(record.created),
"level": record.levelname, "level": record.levelname,
"module": record.name, "module": record.name,
"message": record.getMessage(), "message": record.getMessage(),
} }
for key, value in record.__dict__.items(): for key, value in record.__dict__.items():
if key not in _RESERVED and not key.startswith("_"): if key not in _RESERVED and key not in _OUTPUT_KEYS and not key.startswith("_"):
payload[key] = value payload[key] = value
if record.exc_info: if record.exc_info:
payload["exc_info"] = self.formatException(record.exc_info) # cache the rendered traceback on the record, like stdlib Formatter does
if not record.exc_text:
record.exc_text = self.formatException(record.exc_info)
payload["exc_info"] = record.exc_text
elif record.exc_text: elif record.exc_text:
payload["exc_info"] = record.exc_text payload["exc_info"] = record.exc_text
if record.stack_info: if record.stack_info:
@@ -49,19 +54,27 @@ class JsonLinesFormatter(logging.Formatter):
return json.dumps(payload, default=str) return json.dumps(payload, default=str)
def build_formatter(output: str = "text", fmt=None, datefmt=None) -> logging.Formatter: def build_formatter(output: str = "text", fmt=None, datefmt=None, warnings: list = None) -> logging.Formatter:
"""build the formatter for the chosen output format """build the formatter for the chosen output format
`output="text"` (default) returns the human-readable text formatter, honoring `output="text"` (default) returns the human-readable text formatter, honoring
the raw `fmt`/`datefmt` format-string overrides. `output="json"` returns the the raw `fmt`/`datefmt` format-string overrides. `output="json"` returns the
structured `JsonLinesFormatter` (which ignores `fmt`/`datefmt` it builds structured `JsonLinesFormatter` (which ignores `fmt`/`datefmt` - it builds
fields, not a format string). an unrecognized `output` falls back to text and fields, not a format string). an unrecognized `output` falls back to text and
warns, never raising a bad format arg must not take the app down. warns, never raising - a bad format arg must not take the app down.
`warnings` is the setup-time buffer (see `setup_logging`): passing it appends
the unknown-output warning there instead of emitting immediately, so it lands
in the configured log like the other setup-time warnings rather than only
stderr. `None` (default) preserves the old immediate-emit behavior for direct
callers outside `setup_logging`.
""" """
if output == "json": if output == "json":
return JsonLinesFormatter() return JsonLinesFormatter()
if output != "text": if output != "text":
logging.getLogger(__name__).warning( message = "log_setup: unknown output %r; falling back to 'text'"
"log_setup: unknown output %r; falling back to 'text'", output if warnings is None:
) logging.getLogger(__name__).warning(message, output)
else:
warnings.append((message, output))
return logging.Formatter(fmt or DEFAULT_FORMAT, datefmt or DEFAULT_DATEFMT) return logging.Formatter(fmt or DEFAULT_FORMAT, datefmt or DEFAULT_DATEFMT)
+343 -41
View File
@@ -1,96 +1,377 @@
"""custom namer/rotator + on-start rotation + retention pruning (stdlib only). """custom namer/rotator + on-start rotation + retention pruning (stdlib only).
the stdlib rotating handlers roll a file next to the live file; these helpers the stdlib rotating handlers roll a file next to the live file; these helpers override
override the namer/rotator so rolled files land in `log_dir` and are gzipped when the namer/rotator so rolled files land in `log_dir` and are gzipped when asked, keep
asked, keep the live file at its stable path, and handle the on-start and prune the live file at its stable path, and handle the on-start and prune paths the handlers
paths the handlers don't manage themselves. don't manage themselves.
FOOTGUN: compression is atomic - `_gzip_file` writes to a `.tmp` sibling, verifies it
decompresses, and only then `os.replace`s it onto the final `.gz` and removes the plain.
a crash/OOM/power-loss or failed verify at any point leaves the plain `.log` intact and
no `.gz`, so a corrupt/partial `.gz` is never produced and retention never has to choose
between an intact plain and a corrupt archive.
""" """
import gzip import gzip
import os import os
import re
import shutil import shutil
import time import time
from typing import Callable, Optional, Tuple from typing import Callable, Optional, Tuple
def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]: def _move(source: str, dest: str) -> None:
"""namer: redirect a rolled filename into log_dir, adding .gz when compressing """rename source to dest, falling back to copy+unlink across filesystems
the handler hands us the default rolled path (next to the live file); we keep its FOOTGUN: os.replace is atomic but raises OSError(EXDEV) across filesystems (the
basename but place it under log_dir, and append .gz so the gzipped name matches. container bind-mount / separate-logs-volume case) - falls back to shutil.move so
the roll still lands instead of failing rotation silently. precondition: `dest` is
a free, non-directory path.
"""
try:
os.replace(source, dest)
except OSError:
shutil.move(source, dest)
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 same-stamp roll 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
counter = 1
while True:
candidate = f"{dest}.{counter}"
if not os.path.exists(candidate) and not os.path.exists(candidate + ".gz"):
return candidate
counter += 1
def _gzip_file(source: str, dest: str) -> None:
"""atomically gzip source into dest, then remove source - or leave source untouched
compression is all-or-nothing: writes to `dest + ".tmp"`, verifies that tmp
decompresses cleanly, and only then `os.replace`s it onto `dest` and removes source.
a crash/OOM/power-loss or a failed verify at ANY point removes the tmp and raises with
source intact and no `.gz` at `dest` - so a corrupt/partial `.gz` is never produced and
nothing downstream ever has to choose between an intact plain and a corrupt archive.
the source mtime is carried onto dest so a file keeps its tier position when it
crosses the plain->gz boundary - a fresh write would otherwise make a
just-compressed file look newest and reshuffle tiers.
"""
mtime = _safe_mtime(source)
tmp_dest = dest + ".tmp"
try:
with open(source, "rb") as src, gzip.open(tmp_dest, "wb") as dst:
shutil.copyfileobj(src, dst)
if not _gz_intact(tmp_dest):
raise OSError(f"gzip of {source!r} did not verify")
except BaseException:
try:
os.remove(tmp_dest)
except OSError:
pass
raise
os.replace(tmp_dest, dest)
os.remove(source)
try:
os.utime(dest, (mtime, mtime))
except OSError:
pass
def _gz_intact(path: str) -> bool:
"""return True if the gzip file at path decompresses cleanly end to end
used by `_gzip_file` to verify a freshly-written `.gz` before it replaces the plain
source; reads the whole stream, any failure means "not intact".
"""
try:
with gzip.open(path, "rb") as handle:
while handle.read(1 << 20):
pass
return True
except Exception:
return False
def make_history_namer(
stem: str, log_dir: str, compress: bool = False, plain: bool = False,
clock=time.localtime,
) -> Callable[[str], str]:
"""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. FOOTGUN: prune/retier's
`stem` must match this one or nothing matches and retention silently never fires.
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: def namer(default_name: str) -> str:
base = os.path.basename(default_name) stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock())
target = os.path.join(log_dir, base) base = os.path.join(log_dir, f"{stem}.{stamp}")
return target + ".gz" if compress else target candidate = base
counter = 1
while os.path.exists(candidate + ".log") or os.path.exists(candidate + ".log.gz"):
candidate = f"{base}.{counter}"
counter += 1
suffix = ".log.gz" if (compress and not plain) else ".log"
return candidate + suffix
return namer return namer
def make_rotator( def make_rotator(
compress: bool, log_dir: Optional[str] = None, compress: bool, log_dir: Optional[str] = None,
prune_stem: Optional[str] = None, backup_count: int = 0, prune_stem: Optional[str] = None, backup_count: int = 0,
keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None,
rotate_mode: Optional[str] = None, live_stem: Optional[str] = None,
) -> Callable[[str, str], None]: ) -> Callable[[str, str], None]:
"""rotator: move (or gzip) the source live file to the destination rolled path """rotator: move (or gzip) the source live file to the destination rolled path
prunes `log_dir` to `backup_count` newest rolled files after each roll when legacy mode (default): gzip on roll when `compress`, then prune `log_dir` to
`log_dir`/`prune_stem` are given. the stdlib handler's own retention `backup_count` newest rolled files - the stdlib handler's own retention only scans
(`getFilesToDelete`) only scans the live file's directory, so it never sees the the live file's directory, so it never sees files redirected into `log_dir`; pruning
rolled files we redirect into `log_dir` — pruning here is what actually bounds here is what bounds retention for daily/size. FOOTGUN: for `rotate_mode="size"`,
retention for the daily and size rolling modes. `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. `rotate_mode` gates this delete-on-land branch to `"size"` only - `"daily"`
(and any other non-size mode) with `backup_count <= 0` still rolls without pruning,
matching the documented contract that only `size` always bounds the live file.
tiered mode (when `keep_uncompressed`/`keep_compressed` are given): land the rolled
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
def rotator(source: str, dest: str) -> None: def rotator(source: str, dest: str) -> None:
if not os.path.exists(source): if not os.path.exists(source):
return return
if tiered:
# strip the namer's .gz suffix so the roll lands plain and retier decides
# its tier; disambiguate a same-interval collision via _free_dest
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:
retier(log_dir, prune_stem, keep_uncompressed or 0, keep_compressed or 0, live_stem)
return
if compress: if compress:
with open(source, "rb") as src, gzip.open(dest, "wb") as dst: _gzip_file(source, dest)
shutil.copyfileobj(src, dst)
os.remove(source)
else: else:
os.replace(source, dest) _move(source, dest)
if log_dir is not None and prune_stem is not None: if backup_count <= 0:
prune(log_dir, prune_stem, backup_count) if rotate_mode == "size":
try:
os.remove(dest)
except OSError:
pass
elif log_dir is not None and prune_stem is not None:
prune(log_dir, prune_stem, backup_count, live_stem)
return rotator return rotator
def rotate_on_start(live_path: str, log_dir: str, compress: bool, clock=time.localtime) -> None: def rotate_on_start(
live_path: str, log_dir: str, compress: bool, clock=time.localtime,
keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None,
history_stem: Optional[str] = None,
) -> None:
"""move an existing live file into log_dir with a timestamp, gzipped if asked """move an existing live file into log_dir with a timestamp, gzipped if asked
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 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 (`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): if not os.path.exists(live_path):
return return
stem = os.path.splitext(os.path.basename(live_path))[0] tiered = keep_uncompressed is not None or keep_compressed is not None
live_stem = os.path.splitext(os.path.basename(live_path))[0]
stem = os.path.basename(history_stem) if history_stem else live_stem
stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock()) stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock())
dest = os.path.join(log_dir, f"{stem}.{stamp}.log") suffix = ".log.gz" if (compress and not tiered) else ".log"
if compress:
dest += ".gz" # a 1-second stamp collision (rapid crash-restart) is disambiguated with a
with open(live_path, "rb") as src, gzip.open(dest, "wb") as dst: # counter; check BOTH .log and .log.gz since a tiered same-stamp roll may
shutil.copyfileobj(src, dst) # already be compressed
os.remove(live_path) 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")
dest = os.path.join(log_dir, f"{stem}.{stamp}{suffix}")
counter = 1
while _taken(dest):
dest = os.path.join(log_dir, f"{stem}.{stamp}.{counter}{suffix}")
counter += 1
if compress and not tiered:
_gzip_file(live_path, dest)
else: else:
os.replace(live_path, dest) _move(live_path, dest)
if tiered:
retier(log_dir, stem, keep_uncompressed or 0, keep_compressed or 0, live_stem)
def prune(log_dir: str, stem: str, backup_count: int) -> None: def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int,
live_stem: Optional[str] = None) -> None:
"""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, 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.
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 rather than falling back to listdir order.
candidates are also checked against this lib's own rolled-file shape
(`<stem>.<stamp>[.N].log[.gz]`, see `_is_rolled_name`) - a foreign file that only
shares the `<stem>.` prefix (e.g. a project's own `<stem>.audit.log` dropped into
the same log_dir) is left alone rather than tiered/gzipped/deleted.
"""
stem = os.path.basename(stem)
live_stem = os.path.basename(live_stem) if live_stem else None
try:
names = [
name for name in os.listdir(log_dir)
if name != f"{stem}.log" and _is_rolled_name(stem, name, live_stem)
]
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 os.replace and its
# os.remove(source) can leave <x>.log beside <x>.log.gz. the .gz is guaranteed intact
# (_gzip_file verifies before it replaces, and never produces a partial .gz), so the
# plain twin is redundant and dropped unconditionally.
present = set(entries)
kept = []
for p in entries:
if not p.endswith(".gz") and (p + ".gz") in present:
try:
os.remove(p)
continue
except OSError:
pass # couldn't remove - keep it in the accounting
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, ties broken by higher (later) roll counter
files.sort(key=lambda t: (t[1], t[2]), reverse=True)
keep = keep_uncompressed + keep_compressed
for index, (path, _, _) in enumerate(files):
if index >= keep:
try:
os.remove(path)
except OSError:
pass
elif index >= keep_uncompressed and not path.endswith(".gz"):
dest = path + ".gz"
if os.path.exists(dest):
# a verified .gz twin already exists (a prior crashed roll) - drop the
# redundant plain rather than re-gzip over it
try:
os.remove(path)
except OSError:
pass
continue
try:
_gzip_file(path, dest)
except OSError:
pass
def _rolled_name_pattern(stem: str, live_stem: Optional[str] = None) -> "re.Pattern":
"""compiled regex matching this lib's own rolled-file shapes for stem
all forms are date-bearing so a foreign same-stem file (e.g. `proj.audit.log`) is
never mistaken for a roll and pruned/retiered/deleted:
- current uniform namer: `<stem>.<Y-m-d_H-M-S>[.N].log[.gz]`
(make_history_namer/rotate_on_start, see attach_rolling)
- legacy pre-v0.5.0 daily: `<stem>.log.<Y-m-d>[.gz]` (the stdlib TimedRotatingFileHandler
shape) - matched so an upgraded deployment's existing history is still pruned/retired
instead of piling up forever. legacy rolls were named off the LIVE file's name, not the
history stem, so when `live_stem` is given (and differs) its legacy shape is matched too
"""
stems = [stem] if live_stem is None or live_stem == stem else [stem, live_stem]
forms = []
for s in stems:
esc = re.escape(s)
forms.append(rf"{esc}\.\d{{4}}-\d{{2}}-\d{{2}}_\d{{2}}-\d{{2}}-\d{{2}}(?:\.\d+)?\.log(?:\.gz)?")
forms.append(rf"{esc}\.log\.\d{{4}}-\d{{2}}-\d{{2}}(?:\.gz)?")
return re.compile(rf"^(?:{'|'.join(forms)})$")
def _is_rolled_name(stem: str, name: str, live_stem: Optional[str] = None) -> bool:
"""return whether name has this lib's own rolled-log shape for stem (or the live stem)"""
return _rolled_name_pattern(stem, live_stem).match(name) is not None
def _roll_counter(path: str) -> int:
"""parse the same-second disambiguation counter out of a rolled filename
only the on_start / size-namer shape carries a counter: `<stem>.<stamp>[.<counter>].log`
(optionally `.gz`); a higher counter is the later roll, first roll of a second is 0.
daily's dated names (`<stem>.log.<Y-m-d>`) don't end in `.log`, so they never need
the tie-break - return 0 rather than misparsing the trailing date as a counter.
"""
base = path[:-3] if path.endswith(".gz") else path
if not base.endswith(".log"):
return 0
base = base[:-4]
tail = base.rsplit(".", 1)[-1]
return int(tail) if tail.isdigit() else 0
def prune(log_dir: str, stem: str, backup_count: int, live_stem: Optional[str] = None) -> None:
"""keep only the newest `backup_count` rolled files for a given stem in log_dir """keep only the newest `backup_count` rolled files for a given stem in log_dir
matches files beginning with `<stem>.` (e.g. run.*), sorted by mtime, deleting the matches files beginning with `<stem>.` (e.g. run.*), sorted 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. oldest beyond the count. used for on_start, which the handlers don't auto-prune.
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.
candidates are also checked against this lib's own rolled-file shape
(`<stem>.<stamp>[.N].log[.gz]`, see `_is_rolled_name`) - a foreign file that only
shares the `<stem>.` prefix (e.g. a project's own `<stem>.audit.log` dropped into
the same log_dir) is left alone rather than counted and deleted as a roll.
""" """
if backup_count <= 0: if backup_count <= 0:
return return
stem = os.path.basename(stem)
live_stem = os.path.basename(live_stem) if live_stem else None
try: try:
entries = [ entries = [
os.path.join(log_dir, name) os.path.join(log_dir, name)
for name in os.listdir(log_dir) for name in os.listdir(log_dir)
if name.startswith(f"{stem}.") and name != f"{stem}.log" if name != f"{stem}.log" and _is_rolled_name(stem, name, live_stem)
] ]
except OSError: except OSError:
return return
files = [(p, _safe_mtime(p)) for p in entries if os.path.isfile(p)] files = [(p, _safe_mtime(p), _roll_counter(p)) for p in entries if os.path.isfile(p)]
files.sort(key=lambda pair: pair[1], reverse=True) files.sort(key=lambda t: (t[1], t[2]), reverse=True)
for path, _ in files[backup_count:]: for path, _, _ in files[backup_count:]:
try: try:
os.remove(path) os.remove(path)
except OSError: except OSError:
@@ -108,14 +389,35 @@ def _safe_mtime(path: str) -> float:
def attach_rolling( def attach_rolling(
handler, log_dir: str, compress: bool, handler, log_dir: str, compress: bool,
prune_stem: Optional[str] = None, backup_count: int = 0, prune_stem: Optional[str] = None, backup_count: int = 0,
keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None,
tiered: bool = False, rotate_mode: Optional[str] = None,
) -> Tuple[Callable, Callable]: ) -> Tuple[Callable, Callable]:
"""wire the custom namer + rotator onto a rotating handler; return them """wire the custom namer + rotator onto a rotating handler; return them
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 - 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 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). (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). `rotate_mode`
("size"/"daily") is forwarded to `make_rotator` so the zero-retention delete-on-land
branch only ever fires for `"size"`.
""" """
namer = make_namer(log_dir, compress) namer = make_history_namer(
rotator = make_rotator(compress, log_dir, prune_stem, backup_count) os.path.basename(prune_stem or ""), log_dir, compress, plain=tiered,
)
# the live file name (stem of the handler's baseFilename, minus one .log) - so retention
# also recognizes pre-v0.5.0 legacy rolls, which were named off the LIVE name not the stem
live_base = os.path.basename(getattr(handler, "baseFilename", "") or "")
live_stem = live_base[:-4] if live_base.endswith(".log") else live_base
rotator = make_rotator(
compress, log_dir, prune_stem, backup_count, keep_uncompressed, keep_compressed,
rotate_mode=rotate_mode, live_stem=live_stem or None,
)
handler.namer = namer handler.namer = namer
handler.rotator = rotator handler.rotator = rotator
return namer, rotator return namer, rotator
+187 -66
View File
@@ -1,18 +1,22 @@
"""app-entry-point logging setup (sync, stdlib only). """app-entry-point logging setup (sync, stdlib only). see README.
`setup_logging` configures the root logger once for the whole process: a live `setup_logging` configures the root logger once for the whole process. called by the
run.log at a stable path, rotation (daily/size/on_start/none) into a logs/ dir, gzip APPLICATION, not by reusable libraries (those stay emit-only). idempotent, never
of rolled files, retention, console output, and a consistent format. it is called by crashes the app over logging, and can route through a background queue so an async
the APPLICATION, not by reusable libraries (those stay emit-only). it is idempotent event loop doesn't block on file I/O.
(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` (means "keep zero rolled files", not
"never roll" - each roll is deleted right after landing).
""" """
import atexit import atexit
import logging import logging
import logging.handlers import logging.handlers
import os import os
import queue import queue as _queue
import sys
import traceback
from typing import Dict, Optional, Union from typing import Dict, Optional, Union
from .formats import build_formatter from .formats import build_formatter
@@ -22,27 +26,52 @@ log = logging.getLogger(__name__)
_MARKER = "_log_setup_owned" _MARKER = "_log_setup_owned"
_listener = None _listener = None
_atexit_registered = False
class _PreservingQueueHandler(logging.handlers.QueueHandler):
"""QueueHandler that hands the record to the listener untouched
stdlib's QueueHandler.prepare() calls self.format(record) with the queue
handler's OWN (default) formatter, then nulls exc_info/exc_text/stack_info -
losing structured fields (e.g. JsonLinesFormatter's exc_info key) before the
listener's real formatter ever sees the record. that behavior exists to keep a
record picklable across a multiprocessing.Queue; this lib only ever uses an
in-process queue.Queue, so there is nothing to pickle and nothing to strip -
the listener's handler formats the untouched record exactly once.
"""
def prepare(self, record: logging.LogRecord) -> logging.LogRecord:
return record
def _exc_text() -> str:
"""render sys.exc_info() as text, for capturing a traceback into a buffered warning"""
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"""
for message, *args in warnings:
log.warning(message, *args)
def _level_value(level: Union[int, str]) -> int: def _level_value(level: Union[int, str]) -> int:
"""coerce a level name or int to a logging level int (defaults to INFO)""" """coerce a level name or int to a logging level int (defaults to INFO)"""
if isinstance(level, bool):
# bool is an int subclass (True==1, below DEBUG) but never a real level
return logging.INFO
if isinstance(level, int): if isinstance(level, int):
return level return level
if not isinstance(level, str): if not isinstance(level, str):
return logging.INFO return logging.INFO
resolved = logging.getLevelName(level.upper()) resolved = logging.getLevelName(level.upper())
# getLevelName returns the string "Level XXX" for an unknown name, which # getLevelName returns "Level XXX" for an unknown name; fall back to INFO
# setLevel then rejects — never crash the app over a bad level, fall back to INFO
return resolved if isinstance(resolved, int) else logging.INFO return resolved if isinstance(resolved, int) else logging.INFO
def _strict_level_value(level: Union[int, str]) -> Optional[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 """like _level_value but reports invalid as None so the caller can skip + warn"""
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
"""
if isinstance(level, bool): if isinstance(level, bool):
return None return None
if isinstance(level, int): if isinstance(level, int):
@@ -53,29 +82,30 @@ def _strict_level_value(level: Union[int, str]) -> Optional[int]:
return resolved if isinstance(resolved, int) else None 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 """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.
"""
if not module_levels: if not module_levels:
return return
for mod_name, raw_level in module_levels.items(): for mod_name, raw_level in module_levels.items():
value = _strict_level_value(raw_level) value = _strict_level_value(raw_level)
if value is None: 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 continue
logging.getLogger(mod_name).setLevel(value) logging.getLogger(mod_name).setLevel(value)
def _clear_owned(root: logging.Logger) -> None: def _clear_owned(root: logging.Logger, warnings: list) -> None:
"""remove only the handlers this lib previously added; leave app handlers alone""" """remove only the handlers this lib previously added; leave app handlers alone"""
global _listener global _listener
if _listener is not None: if _listener is not None:
_listener.stop() _listener.stop()
# listener owns the real file/console handlers; 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:
warnings.append(("log_setup: failed to close queued handler %r: %s", wrapped, _exc_text()))
_listener = None _listener = None
for handler in list(root.handlers): for handler in list(root.handlers):
if getattr(handler, _MARKER, False): if getattr(handler, _MARKER, False):
@@ -83,7 +113,9 @@ def _clear_owned(root: logging.Logger) -> None:
try: try:
handler.close() handler.close()
except Exception: except Exception:
pass warnings.append(
("log_setup: failed to close handler %r during re-setup: %s", handler, _exc_text())
)
def _tag(handler: logging.Handler) -> logging.Handler: def _tag(handler: logging.Handler) -> logging.Handler:
@@ -92,25 +124,77 @@ def _tag(handler: logging.Handler) -> logging.Handler:
return handler return handler
def _normalize_name(name: str) -> str:
"""strip one trailing '.log' (case-insensitive) so the stem is extension-free
"latest" and "latest.log" both yield stem "latest" (never latest.log.log); only
one level is stripped, so "app.log.log" -> "app.log".
"""
if name.lower().endswith(".log"):
return name[:-4]
return name
def _history_stem() -> str:
"""the project namespace for historic files: the cwd basename, "" for a degenerate cwd"""
try:
return os.path.basename(os.getcwd().rstrip(os.sep))
except OSError:
return ""
def _file_handler( def _file_handler(
name: str, live_path: str, log_dir: str, rotate: Optional[str], history_stem: str, live_path: str, log_dir: str, rotate: Optional[str],
backup_count: int, max_bytes: int, compress: bool, backup_count: int, max_bytes: int, compress: bool,
keep_uncompressed: Optional[int], keep_compressed: Optional[int], warnings: list,
) -> logging.Handler: ) -> logging.Handler:
"""build the configured file handler with custom rolling into log_dir""" """build the configured file handler with custom rolling into log_dir
`history_stem` is the PROJECT stem that rolled/historic files are named off,
decoupled from the live file's own name (`live_path`).
"""
tiered = keep_uncompressed is not None or keep_compressed is not None
if rotate == "size": if rotate == "size":
# stdlib doRollover no-ops at backupCount==0 - force nonzero so the roll
# always fires; the REAL backup_count still flows to attach_rolling, whose
# make_rotator treats <=0 as "keep no rolled history" and deletes each roll
size_backup = max(backup_count, 1)
handler = logging.handlers.RotatingFileHandler( handler = logging.handlers.RotatingFileHandler(
live_path, maxBytes=max_bytes, backupCount=backup_count, encoding="utf-8", live_path, maxBytes=max_bytes, backupCount=size_backup, encoding="utf-8",
)
attach_rolling(
handler, log_dir, compress, prune_stem=history_stem, backup_count=backup_count,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
tiered=tiered, rotate_mode=rotate,
) )
attach_rolling(handler, log_dir, compress, prune_stem=name, backup_count=backup_count)
elif rotate == "daily": elif rotate == "daily":
handler = logging.handlers.TimedRotatingFileHandler( handler = logging.handlers.TimedRotatingFileHandler(
live_path, when="midnight", backupCount=backup_count, encoding="utf-8", live_path, when="midnight", backupCount=backup_count, encoding="utf-8",
) )
attach_rolling(handler, log_dir, compress, prune_stem=name, backup_count=backup_count) attach_rolling(
handler, log_dir, compress, prune_stem=history_stem, backup_count=backup_count,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
tiered=tiered, rotate_mode=rotate,
)
else: else:
if rotate == "on_start": if rotate == "on_start":
rotate_on_start(live_path, log_dir, compress) if tiered:
prune(log_dir, name, backup_count) rotate_on_start(
live_path, log_dir, compress, history_stem=history_stem,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
)
else:
rotate_on_start(live_path, log_dir, compress, history_stem=history_stem)
live_base = os.path.basename(live_path)
live_stem = live_base[:-4] if live_base.endswith(".log") else live_base
prune(log_dir, history_stem, backup_count, live_stem or None)
elif rotate is not None:
# a typo'd value 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") handler = logging.FileHandler(live_path, encoding="utf-8")
return handler return handler
@@ -121,7 +205,10 @@ def setup_logging(
level: Union[int, str] = "INFO", level: Union[int, str] = "INFO",
module_levels: Optional[Dict[str, Union[int, str]]] = None, module_levels: Optional[Dict[str, Union[int, str]]] = None,
rotate: Optional[str] = "daily", rotate: Optional[str] = "daily",
history_name: Optional[str] = None,
backup_count: int = 14, backup_count: int = 14,
keep_uncompressed: Optional[int] = None,
keep_compressed: Optional[int] = None,
max_bytes: int = 10_000_000, max_bytes: int = 10_000_000,
compress: bool = True, compress: bool = True,
console: bool = False, console: bool = False,
@@ -132,37 +219,62 @@ def setup_logging(
) -> logging.Logger: ) -> logging.Logger:
"""configure the root logger for the whole process and return it """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`. `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
latest.log (never latest.log.log).
`history_name` names the rolled/historic files (`<history_name>.<timestamp>.log[.gz]`),
independent of the live file: defaults to the PROJECT namespace = the cwd basename
(run from bestbuy/ -> historic files bestbuy.<stamp>...). 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, 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 `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 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 to quiet noisy dependencies (e.g. {"motor": "WARNING"}) from one call instead of
the one setup call instead of scattering `getLogger(...).setLevel(...)` afterwards — scattering `getLogger(...).setLevel(...)` calls. names match EXACTLY (no discovery:
it's stdlib hierarchy under the hood, not new capability. names match EXACTLY (no a typo'd name silently configures an unused logger), but hierarchy applies, so
discovery: a typo'd name silently configures an unused logger), but stdlib hierarchy naming a parent ("aiohttp") quiets its whole subtree. str or int per entry; a bad
applies, so naming a parent ("aiohttp") quiets its whole subtree (aiohttp.client, value is skipped with a warning and never aborts the others or the setup.
aiohttp.access, ...). each entry accepts a str or int level; a bad value for one
entry is skipped with a warning and never aborts the others or the setup. `rotate` is "daily" (default), "size", "on_start", or None. for `rotate="size"`, the
`rotate` is "daily" (default), "size", "on_start", or None. `console=True` adds a live file always rolls at `max_bytes` regardless of `backup_count`: `backup_count=0`
stdout handler (off by default — the file is the output). `queue=True` routes records means "keep zero rolled files" (each roll lands then is deleted immediately), NOT
through a background QueueListener so file I/O never blocks the caller (the listener "disable rotation". `backup_count>=1` keeps that many rolled files as before.
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 `console=True` adds a stdout handler (off by default - the file is the output).
Grafana/Loki path, UTC timestamps, `extra=` fields surfaced as top-level keys); both `queue=True` routes records through a background QueueListener so file I/O never
file and console use the chosen format and the live-file name is the same regardless. blocks the caller (stopped at exit). `output` is "text" (default, human `time |
the raw `fmt`/`datefmt` overrides apply to text output only. idempotent: a repeat call module | level | message`, local time) or "json" (structured JSON Lines, UTC
clears only the handlers this function added. never raises over logging — an timestamps + a unix-epoch `ts`, `extra=` fields surfaced as top-level keys); file
unwritable `log_dir` falls back to console-only with a warning even when `console` is and console use the same format, live-file name unaffected. `fmt`/`datefmt` apply
off, so output is never silently lost; an unknown `output` falls back to text. 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 global _listener, _atexit_registered
warnings: list = []
root = logging.getLogger() root = logging.getLogger()
root.setLevel(_level_value(level)) root.setLevel(_level_value(level))
_apply_module_levels(module_levels) _apply_module_levels(module_levels, warnings)
_clear_owned(root) _clear_owned(root, warnings)
formatter = build_formatter(output, fmt, datefmt) formatter = build_formatter(output, fmt, datefmt, warnings)
live_path = f"{name}.log" stem = _normalize_name(name)
live_path = f"{stem}.log"
# history_name if given, else the cwd basename; 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
handlers = [] handlers = []
@@ -174,37 +286,46 @@ def setup_logging(
if file_ok: if file_ok:
try: try:
fh = _file_handler(name, live_path, log_dir, rotate, backup_count, max_bytes, compress) fh = _file_handler(
history_stem, live_path, log_dir, rotate, backup_count, max_bytes, compress,
keep_uncompressed, keep_compressed, warnings,
)
fh.setFormatter(formatter) fh.setFormatter(formatter)
handlers.append(fh) handlers.append(fh)
except OSError: except OSError:
file_ok = False file_ok = False
if console or not file_ok: if console or not file_ok:
sh = logging.StreamHandler() sh = logging.StreamHandler(sys.stdout)
sh.setFormatter(formatter) sh.setFormatter(formatter)
handlers.append(sh) handlers.append(sh)
if queue: if queue:
record_queue: "queue.Queue" = _make_queue() record_queue: "_queue.Queue" = _make_queue()
qh = _tag(logging.handlers.QueueHandler(record_queue)) qh = _tag(_PreservingQueueHandler(record_queue))
root.addHandler(qh) root.addHandler(qh)
_listener = logging.handlers.QueueListener(record_queue, *handlers, respect_handler_level=True) _listener = logging.handlers.QueueListener(record_queue, *handlers, respect_handler_level=True)
_listener.start() _listener.start()
atexit.register(_stop_listener) if not _atexit_registered:
# register once - atexit doesn't dedupe, repeated re-setups would stack
atexit.register(_stop_listener)
_atexit_registered = True
else: else:
for handler in handlers: for handler in handlers:
root.addHandler(_tag(handler)) root.addHandler(_tag(handler))
if not file_ok: 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 warnings land in the configured log
_flush_warnings(warnings)
return root return root
def _make_queue() -> "queue.Queue": def _make_queue() -> "_queue.Queue":
"""unbounded in-memory queue for the QueueHandler -> QueueListener path""" """unbounded in-memory queue for the QueueHandler -> QueueListener path"""
return queue.Queue(-1) return _queue.Queue(-1)
def _stop_listener() -> None: def _stop_listener() -> None: