6 Commits
Author SHA1 Message Date
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
6 changed files with 472 additions and 155 deletions
+81 -19
View File
@@ -13,12 +13,12 @@ and emit; their records flow into the handlers `log_setup` wired.
## Install ## Install
``` ```
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.4.0 log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.0
``` ```
No dependencies — stdlib only. No dependencies — stdlib only.
Drop the `@v0.4.0` 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 ## Quick start
@@ -43,21 +43,48 @@ 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
`<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 - **Retention** = `backup_count` (default 14) for every mode — unless tiered retention is
enabled (below). enabled (below). For `rotate="size"`, `backup_count=0` is "keep none" (not "disable
rotation") — see the `size` bullet above and the note at the bottom of this section.
- **console=True** (off by default) also logs to stdout in the same format — opt in when - **console=True** (off by default) also logs to stdout in the same format — opt in when
you want live terminal output alongside the file. you want live terminal output alongside the file.
The `name` you pass is normalized so it produces exactly one `.log`: `name="latest"` and 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`). `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`) ## Tiered retention (`keep_uncompressed` / `keep_compressed`)
The default is a flat `backup_count`: every rolled file is gzipped on roll and the oldest The default is a flat `backup_count`: every rolled file is gzipped on roll and the oldest
@@ -65,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: without `zcat`) and older ones **gzipped**, pass the two tier knobs:
```python ```python
# app run from bestbuy/run.py , with name="latest":
setup_logging( setup_logging(
name="latest", name="latest",
rotate="on_start", # works for on_start, daily, and size rotate="on_start", # works for on_start, daily, and size
@@ -73,13 +101,15 @@ setup_logging(
) )
``` ```
Result in `log_dir` (newest → oldest): Result — the live file stays at its stable path in cwd; `log_dir` (default `logs/`) holds
the tiered historic files, named off the project stem (newest → oldest):
``` ```
latest.log <- live "latest" (stable, tail -f) ./latest.log <- live (stable, tail -f, in cwd)
latest.<t1>.log latest.<t2>.log latest.<t3>.log <- 3 newest: plain logs/
latest.<t4>.log.gz ... latest.<t10>.log.gz <- next 7: gzipped bestbuy.<t1>.log bestbuy.<t2>.log bestbuy.<t3>.log <- 3 newest: plain
(anything past 10 deleted) 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`, - Each restart (`on_start`) or roll (`daily`/`size`) moves the live file into `log_dir`,
@@ -109,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.
@@ -133,6 +168,7 @@ 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
history_name=None, # stem for rolled/historic files; None -> cwd basename (project)
backup_count=14, # rotated files to keep (flat retention; ignored if tiered) 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_uncompressed=None, # tiered: newest N rolled logs kept PLAIN (opt-in)
keep_compressed=None, # tiered: next M rolled logs kept GZIPPED (opt-in) keep_compressed=None, # tiered: next M rolled logs kept GZIPPED (opt-in)
@@ -204,6 +240,32 @@ setup_logging(name="run", queue=True)
duplicate lines) and leaves handlers your app added itself alone. duplicate lines) and leaves handlers your app added itself alone.
- **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to - **Never crashes the app over logging:** if `log_dir` isn't writable, it falls back to
console-only with a warning instead of raising. console-only with a warning instead of raising.
- **`rotate="size"` always bounds the live file (v0.5.1+).** Previously, `backup_count=0`
with `rotate="size"` silently disabled rotation entirely (the live file grew forever,
ignoring `max_bytes`). As of v0.5.1, the live file always rolls at `max_bytes`
regardless of `backup_count`; `backup_count=0` means "keep zero rolled files" (each roll
is deleted right after it lands) rather than "never roll." `backup_count>=1` behaves as
documented (keeps that many rolled files). This does not change `"daily"`/`"on_start"`,
where `backup_count=0` still means "roll, but don't prune the rolled files" (unbounded
`log_dir` growth) — that is a separate, pre-existing knob, not this fix's scope.
- **Gzip writes are crash-safe (v0.5.1+).** `_gzip_file` now writes to a `.tmp` sibling and
atomically `os.replace`s it onto the final `.gz` path, so a crash/OOM/power-loss mid-write
can never leave a truncated `.gz` at the path retention logic trusts. Tiered retention's
plain/gz dedupe additionally verifies a `.gz` decompresses cleanly before deleting its
plain twin — a corrupt `.gz` (from before this fix, or an external cause) is never
preferred over an intact plain copy; the plain is kept and the `.gz` gets rewritten
cleanly on the next retier pass instead of being deleted.
- **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
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project] [project]
name = "log_setup" name = "log_setup"
version = "0.4.0" version = "0.6.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 = []
+4 -4
View File
@@ -1,14 +1,14 @@
"""log_setup — app-entry-point logging configuration (sync, stdlib only). """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 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 run.log, rotation (daily/size/on_start), gzip of rolled files, retention, optional
output, and a consistent `time | module | level | message` format. 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 — they only `logging.getLogger(__name__)` and
emit; the application owns this setup. shipping logs to a backend is out of scope 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"] __all__ = ["setup_logging"]
__version__ = "0.4.0" __version__ = "0.6.0"
+14 -11
View File
@@ -16,28 +16,31 @@ 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 # 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 # colliding with real attribute names (e.g. `module`), but `time`/`level`/`ts` are NOT
# LogRecord attrs, so a caller's extra={"time":...}/{"level":...} would otherwise # LogRecord attrs, so a caller's extra={"time":...}/{"ts":...} would otherwise overwrite
# overwrite the UTC timestamp / levelname. guard them explicitly # the UTC timestamp / epoch. guard them explicitly
_OUTPUT_KEYS = frozenset({"time", "level", "module", "message"}) _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 (e.g. 2026-06-28T14:03:11Z); `ts` (added v0.6.0) is the same instant as a
containers sort unambiguously — Grafana converts to local for display. any unix epoch int (`int(record.created)`, second resolution) for a consumer that wants
field passed via logging `extra={...}` lands as a top-level JSON field, which a sortable number instead of parsing the ISO string — both sort unambiguously
is how a caller stamps monitor/service/request-id for Loki labels without the across machines/containers; Grafana converts to local for display. any field
lib knowing those domain concepts. a traceback (exc_info) is rendered into an passed via logging `extra={...}` lands as a top-level JSON field (how a caller
`exc_info` string field rather than dropped. 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: 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(),
+220 -55
View File
@@ -1,9 +1,15 @@
"""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.
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 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 import gzip
@@ -16,15 +22,13 @@ from typing import Callable, Optional, Tuple
def _move(source: str, dest: str) -> None: def _move(source: str, dest: str) -> None:
"""rename source to dest, falling back to copy+unlink across filesystems """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 os.replace is atomic but raises OSError(EXDEV) across filesystems — the container
different filesystems — exactly the container bind-mount / separate-logs-volume bind-mount / separate-logs-volume case this lib targets. falls back to shutil.move
case this lib targets. fall back to shutil.move (copy+unlink) so the roll still (copy+unlink) so the roll still lands instead of failing rotation silently.
lands instead of failing every rotation via the handler's silent handleError.
precondition: `dest` is a free, non-directory path (all call sites generate a unique precondition: `dest` is a free, non-directory path (every call site generates a
timestamped/dated dest). os.replace and shutil.move differ on a dest that already unique timestamped/dated dest) — not safe for arbitrary dests that may already
exists as a directory, so this helper is not safe for arbitrary dests — only the exist as a directory.
rotation paths that guarantee a fresh file dest.
""" """
try: try:
os.replace(source, dest) os.replace(source, dest)
@@ -32,16 +36,47 @@ def _move(source: str, dest: str) -> None:
shutil.move(source, dest) 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 roll landing on the same dated/stamped name
(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
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: def _gzip_file(source: str, dest: str) -> None:
"""gzip source into dest then remove source (the rolled-file compression idiom) """gzip source into dest then remove source (the rolled-file compression idiom)
the source mtime is carried onto dest so a file keeps its position when it crosses writes to `dest + ".tmp"` and atomically `os.replace`s it onto `dest` once
the plain->gz tier boundary — retier ranks by mtime, and a fresh write would complete, so a crash/OOM/power-loss mid-write never leaves a truncated `.gz` at
otherwise make a just-compressed file look like the newest one and reshuffle tiers. `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 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) mtime = _safe_mtime(source)
with open(source, "rb") as src, gzip.open(dest, "wb") as dst: tmp_dest = dest + ".tmp"
try:
with open(source, "rb") as src, gzip.open(tmp_dest, "wb") as dst:
shutil.copyfileobj(src, dst) shutil.copyfileobj(src, dst)
except BaseException:
try:
os.remove(tmp_dest)
except OSError:
pass
raise
os.replace(tmp_dest, dest)
os.remove(source) os.remove(source)
try: try:
os.utime(dest, (mtime, mtime)) os.utime(dest, (mtime, mtime))
@@ -49,11 +84,28 @@ def _gzip_file(source: str, dest: str) -> None:
pass pass
def _gz_intact(path: str) -> bool:
"""return True if the gzip file at path decompresses cleanly end to end
belt-and-suspenders check before a dedupe site removes a plain twin in favor of its
.gz — a truncated/corrupt .gz 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:
while handle.read(1 << 20):
pass
return True
except Exception:
return False
def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]: def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]:
"""namer: redirect a rolled filename into log_dir, adding .gz when compressing """namer: redirect a rolled filename into log_dir, adding .gz when compressing
the handler hands us the default rolled path (next to the live file); we keep its keeps the handler's default rolled basename but places it under log_dir, appending
basename but place it under log_dir, and append .gz so the gzipped name matches. .gz so the gzipped name matches.
""" """
def namer(default_name: str) -> str: def namer(default_name: str) -> str:
base = os.path.basename(default_name) base = os.path.basename(default_name)
@@ -62,6 +114,35 @@ def make_namer(log_dir: str, compress: bool) -> Callable[[str], str]:
return namer return namer
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 must
glob this same stem 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:
stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock())
base = os.path.join(log_dir, f"{stem}.{stamp}")
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
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,
@@ -70,15 +151,16 @@ def make_rotator(
"""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
legacy mode (default): gzip on roll when `compress`, then prune `log_dir` to legacy mode (default): gzip on roll when `compress`, then prune `log_dir` to
`backup_count` newest rolled files. 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 bounds retention for here is what bounds retention for daily/size. FOOTGUN: `backup_count <= 0` means
the daily and size rolling modes. "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 tiered mode (when `keep_uncompressed`/`keep_compressed` are given): land the rolled
file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, the file PLAIN and re-tier `log_dir` — newest `keep_uncompressed` stay uncompressed, next
next `keep_compressed` are gzipped, the rest deleted. `compress`/`backup_count` are `keep_compressed` gzipped, rest deleted. `compress`/`backup_count` are ignored.
ignored in this mode (the tier counts bound retention instead).
""" """
tiered = keep_uncompressed is not None or keep_compressed is not None tiered = keep_uncompressed is not None or keep_compressed is not None
@@ -86,9 +168,11 @@ def make_rotator(
if not os.path.exists(source): if not os.path.exists(source):
return return
if tiered: if tiered:
# dest carries the namer's .gz suffix in compress mode; strip it so the # dest carries the namer's .gz suffix in compress mode; strip it so the roll
# freshly-rolled file lands plain and retier decides its tier # lands plain and retier decides its tier. disambiguate a dest that already
plain_dest = dest[:-3] if dest.endswith(".gz") else dest # 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) _move(source, plain_dest)
if log_dir is not None and prune_stem is not None: 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) retier(log_dir, prune_stem, keep_uncompressed or 0, keep_compressed or 0)
@@ -97,7 +181,12 @@ def make_rotator(
_gzip_file(source, dest) _gzip_file(source, dest)
else: else:
_move(source, dest) _move(source, dest)
if log_dir is not None and prune_stem is not None: if backup_count <= 0:
try:
os.remove(dest)
except OSError:
pass
elif log_dir is not None and prune_stem is not None:
prune(log_dir, prune_stem, backup_count) prune(log_dir, prune_stem, backup_count)
return rotator return rotator
@@ -105,30 +194,34 @@ def make_rotator(
def rotate_on_start( def rotate_on_start(
live_path: str, log_dir: str, compress: bool, clock=time.localtime, live_path: str, log_dir: str, compress: bool, clock=time.localtime,
keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None, keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None,
history_stem: Optional[str] = None,
) -> 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
no-op if the live file doesn't exist. used by rotate="on_start" before the fresh named off `history_stem` (the project namespace) when given, so historic files
handler opens a new live file. the timestamp form is run.<%Y-%m-%d_%H-%M-%S>.log. 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.
tiered mode (when `keep_uncompressed`/`keep_compressed` are given): the rolled file no-op if the live file doesn't exist. used by rotate="on_start" before the fresh
always lands PLAIN (so it can occupy the newest uncompressed tier) and `retier` handler opens a new live file. timestamp form is run.<%Y-%m-%d_%H-%M-%S>.log.
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): if not os.path.exists(live_path):
return return
tiered = keep_uncompressed is not None or keep_compressed is not None tiered = keep_uncompressed is not None or keep_compressed is not None
stem = os.path.splitext(os.path.basename(live_path))[0] 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())
suffix = ".log.gz" if (compress and not tiered) else ".log" 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: def _taken(path: str) -> bool:
base = path[:-3] if path.endswith(".gz") else path base = path[:-3] if path.endswith(".gz") else path
return os.path.exists(base) or os.path.exists(base + ".gz") return os.path.exists(base) or os.path.exists(base + ".gz")
@@ -150,11 +243,20 @@ 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 """re-tier rolled files for stem: newest plain, next gzipped, rest deleted
newest-first by mtime: the first `keep_uncompressed` stay uncompressed, the next 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 `keep_compressed` are gzipped in place, everything beyond
to <name>.gz and the plain source removed), and everything beyond
keep_uncompressed+keep_compressed is deleted. the live <stem>.log is never touched. 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. 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.
""" """
stem = os.path.basename(stem)
try: try:
names = [ names = [
name for name in os.listdir(log_dir) name for name in os.listdir(log_dir)
@@ -163,11 +265,30 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
except OSError: except OSError:
return return
entries = [os.path.join(log_dir, name) for name in names] entries = [os.path.join(log_dir, name) for name in names]
files = [(p, _safe_mtime(p)) for p in entries if os.path.isfile(p)] # dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove
files.sort(key=lambda pair: pair[1], reverse=True) # 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:
if not p.endswith(".gz") and (p + ".gz") in present:
if _gz_intact(p + ".gz"):
try:
os.remove(p)
except OSError:
kept.append(p) # couldn't remove — keep it in the accounting
continue
# .gz twin is corrupt — 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, tied second broken by higher roll counter (later)
files.sort(key=lambda t: (t[1], t[2]), reverse=True)
keep = keep_uncompressed + keep_compressed keep = keep_uncompressed + keep_compressed
for index, (path, _) in enumerate(files): for index, (path, _, _) in enumerate(files):
if index >= keep: if index >= keep:
try: try:
os.remove(path) os.remove(path)
@@ -176,21 +297,56 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
elif index >= keep_uncompressed and not path.endswith(".gz"): elif index >= keep_uncompressed and not path.endswith(".gz"):
dest = path + ".gz" dest = path + ".gz"
if os.path.exists(dest): if os.path.exists(dest):
# 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)
except OSError:
pass
continue continue
# .gz is corrupt — fall through and re-gzip the plain over the bad dest
# (atomic write replaces it only once a valid archive exists)
try: try:
_gzip_file(path, dest) _gzip_file(path, dest)
except OSError: except OSError:
pass pass
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`), where a colliding same-second roll gets `.1`, `.2`, ... and a higher
counter is the later (newer) roll. the first roll of a second has no counter (0).
daily's dated names (`<stem>.log.<Y-m-d>`) do NOT end in `.log` and are second+-granular
(distinct mtimes), so they never need the counter tie-break — return 0 for them rather
than misparsing the trailing date component 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) -> None: def prune(log_dir: str, stem: str, backup_count: int) -> None:
"""keep only the newest `backup_count` rolled files for a given stem in log_dir """keep only the newest `backup_count` rolled files for a given stem in log_dir
matches files beginning with `<stem>.` (e.g. run.*), sorted by mtime, deleting the matches files beginning with `<stem>.` (e.g. run.*), sorted 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.
""" """
if backup_count <= 0: if backup_count <= 0:
return return
stem = os.path.basename(stem)
try: try:
entries = [ entries = [
os.path.join(log_dir, name) os.path.join(log_dir, name)
@@ -199,9 +355,9 @@ def prune(log_dir: str, stem: str, backup_count: int) -> None:
] ]
except OSError: except OSError:
return return
files = [(p, _safe_mtime(p)) for p in entries if os.path.isfile(p)] files = [(p, _safe_mtime(p), _roll_counter(p)) for p in entries if os.path.isfile(p)]
files.sort(key=lambda pair: pair[1], reverse=True) 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:
@@ -220,15 +376,24 @@ 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, keep_uncompressed: Optional[int] = None, keep_compressed: Optional[int] = None,
tiered: bool = False,
) -> 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). pass (the handler's own retention can't see the redirected files). pass
`keep_uncompressed`/`keep_compressed` instead to use tiered retention (newest plain, `keep_uncompressed`/`keep_compressed` for tiered retention instead (see
next gzipped, rest deleted) — see make_rotator. make_rotator); `tiered=True` lands rolls plain (retier compresses).
""" """
namer = make_namer(log_dir, compress) namer = make_history_namer(
os.path.basename(prune_stem or ""), log_dir, compress, plain=tiered,
)
rotator = make_rotator( rotator = make_rotator(
compress, log_dir, prune_stem, backup_count, keep_uncompressed, keep_compressed, compress, log_dir, prune_stem, backup_count, keep_uncompressed, keep_compressed,
) )
+150 -63
View File
@@ -2,10 +2,14 @@
`setup_logging` configures the root logger once for the whole process: a live `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 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 of rolled files, retention, console output, and a consistent format. called by the
the APPLICATION, not by reusable libraries (those stay emit-only). it is idempotent APPLICATION, not by reusable libraries (those stay emit-only). idempotent (no
(no duplicate handlers on repeat calls), never crashes the app over logging, and can duplicate handlers on repeat calls), never crashes the app over logging, and can
route through a background queue so an async event loop doesn't block on file I/O. route through a background queue so an async event loop doesn't block on file I/O.
`rotate="size"` always bounds the live file: the roll fires at `max_bytes` regardless
of `backup_count`, including `backup_count=0` (means "keep zero rolled files", not
"never roll" — each roll is deleted right after landing).
""" """
import atexit import atexit
@@ -13,6 +17,8 @@ import logging
import logging.handlers import logging.handlers
import os import os
import queue as _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
@@ -25,6 +31,26 @@ _listener = None
_atexit_registered = False _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: 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): if isinstance(level, bool):
@@ -44,9 +70,8 @@ def _level_value(level: Union[int, str]) -> int:
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 """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 unlike `_level_value` (falls back to INFO for the root `level`), reports invalid as
an invalid value as None so the per-module path can skip + warn rather than silently None so the per-module path can skip + warn instead of silently applying INFO
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
@@ -58,37 +83,40 @@ 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 names match exactly (no discovery); stdlib hierarchy still applies, so a parent name
matched 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`
quiets its whole subtree. a bad level for one entry is skipped with a warning so the (no handlers exist yet — see _flush_warnings) rather than emitted directly
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
close failures are appended to `warnings`, not logged directly — no handlers exist
yet at this point in setup (see _flush_warnings)
"""
global _listener global _listener
if _listener is not None: if _listener is not None:
_listener.stop() _listener.stop()
# the listener owns the real file/console handlers (only the QueueHandler is # listener owns the real file/console handlers (only QueueHandler is root-
# root-attached + marked); stopping it doesn't close them, so close them here # attached + marked); stopping it doesn't close them, so close here rather than
# to avoid relying on GC finalizers across a re-setup # rely on GC finalizers across a re-setup
for wrapped in getattr(_listener, "handlers", ()): for wrapped in getattr(_listener, "handlers", ()):
try: try:
wrapped.close() wrapped.close()
except Exception: 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 _listener = None
for handler in list(root.handlers): for handler in list(root.handlers):
if getattr(handler, _MARKER, False): if getattr(handler, _MARKER, False):
@@ -96,9 +124,9 @@ def _clear_owned(root: logging.Logger) -> None:
try: try:
handler.close() handler.close()
except Exception: except Exception:
# a handler failing to close must not abort re-setup, but log it warnings.append(
# rather than swallow silently (consistent with the lib's warn pattern) ("log_setup: failed to close handler %r during re-setup: %s", handler, _exc_text())
log.warning("log_setup: failed to close handler %r during re-setup", handler, exc_info=True) )
def _tag(handler: logging.Handler) -> logging.Handler: def _tag(handler: logging.Handler) -> logging.Handler:
@@ -120,39 +148,76 @@ def _normalize_name(name: str) -> str:
return name return name
def _history_stem() -> str:
"""the project namespace for historic files: the cwd basename
a service run from bestbuy/ gives historic files bestbuy.<stamp>.log[.gz]. falls back
to an empty string only for a degenerate cwd (e.g. "/"), which the caller resolves to
the live stem.
"""
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], name: 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], 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
`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 — 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 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, 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( 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( attach_rolling(
handler, log_dir, compress, prune_stem=name, backup_count=backup_count, handler, log_dir, compress, prune_stem=history_stem, backup_count=backup_count,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed, keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
tiered=tiered,
) )
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( attach_rolling(
handler, log_dir, compress, prune_stem=name, backup_count=backup_count, handler, log_dir, compress, prune_stem=history_stem, backup_count=backup_count,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed, keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
tiered=tiered,
) )
else: else:
if rotate == "on_start": if rotate == "on_start":
if tiered: if tiered:
rotate_on_start( rotate_on_start(
live_path, log_dir, compress, live_path, log_dir, compress, history_stem=history_stem,
keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed, keep_uncompressed=keep_uncompressed, keep_compressed=keep_compressed,
) )
else: else:
rotate_on_start(live_path, log_dir, compress) rotate_on_start(live_path, log_dir, compress, history_stem=history_stem)
prune(log_dir, name, backup_count) prune(log_dir, history_stem, backup_count)
elif rotate is not None:
# 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") handler = logging.FileHandler(live_path, encoding="utf-8")
return handler return handler
@@ -163,6 +228,7 @@ 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_uncompressed: Optional[int] = None,
keep_compressed: Optional[int] = None, keep_compressed: Optional[int] = None,
@@ -177,46 +243,63 @@ def setup_logging(
"""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`. a `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 trailing ".log" in `name` is stripped so "latest" and "latest.log" both produce
live file latest.log (never latest.log.log). 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>...), 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 `keep_uncompressed`/`keep_compressed` (default None) enable TIERED retention: when
either is given, rolled files are kept as the newest `keep_uncompressed` uncompressed 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 = + the next `keep_compressed` gzipped, rest deleted (total retained = sum). applies to
sum). this applies to "on_start", "daily", and "size". `backup_count` and the "on_start", "daily", and "size". `backup_count` and gzip-on-roll `compress` are
gzip-on-roll behavior of `compress` are IGNORED in tiered mode (the tier counts bound IGNORED in tiered mode. pass NEITHER knob and rotation behaves exactly as before.
retention). pass NEITHER knob and rotation behaves exactly as before (backup_count +
compress) — existing callers are unaffected.
`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 the one setup call
the one setup call instead of scattering `getLogger(...).setLevel(...)` afterwards instead of scattering `getLogger(...).setLevel(...)` afterwards (stdlib hierarchy
it's stdlib hierarchy under the hood, not new capability. names match EXACTLY (no under the hood, not new capability). names match EXACTLY (no discovery: a typo'd
discovery: a typo'd name silently configures an unused logger), but stdlib hierarchy name silently configures an unused logger), but hierarchy applies, so naming a
applies, so naming a parent ("aiohttp") quiets its whole subtree (aiohttp.client, parent ("aiohttp") quiets its whole subtree. str or int per entry; a bad value is
aiohttp.access, ...). each entry accepts a str or int level; a bad value for one skipped with a warning and never aborts the others or the setup.
entry is skipped with a warning and never aborts the others or the setup.
`rotate` is "daily" (default), "size", "on_start", or None. `console=True` adds a `rotate` is "daily" (default), "size", "on_start", or None. for `rotate="size"`, the
stdout handler (off by default — the file is the output). `queue=True` routes records live file always rolls at `max_bytes` regardless of `backup_count`: `backup_count=0`
through a background QueueListener so file I/O never blocks the caller (the listener means "keep zero rolled files" (each roll lands then is deleted immediately), NOT
is stopped at exit). `output` is "text" (default, human `time | module | level | "disable rotation". `backup_count>=1` keeps that many rolled files as before.
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 `console=True` adds a stdout handler (off by default — the file is the output).
file and console use the chosen format and the live-file name is the same regardless. `queue=True` routes records through a background QueueListener so file I/O never
the raw `fmt`/`datefmt` overrides apply to text output only. idempotent: a repeat call blocks the caller (stopped at exit). `output` is "text" (default, human `time |
clears only the handlers this function added. never raises over logging — an module | level | message`, local time) or "json" (structured JSON Lines for the
unwritable `log_dir` falls back to console-only with a warning even when `console` is Grafana/Loki path, UTC timestamps + a unix-epoch `ts`, `extra=` fields surfaced as
off, so output is never silently lost; an unknown `output` falls back to text. 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 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)
stem = _normalize_name(name) stem = _normalize_name(name)
live_path = f"{stem}.log" live_path = f"{stem}.log"
# 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
handlers = [] handlers = []
@@ -229,8 +312,8 @@ def setup_logging(
if file_ok: if file_ok:
try: try:
fh = _file_handler( fh = _file_handler(
stem, live_path, log_dir, rotate, backup_count, max_bytes, compress, 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) fh.setFormatter(formatter)
handlers.append(fh) handlers.append(fh)
@@ -249,8 +332,8 @@ def setup_logging(
_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()
if not _atexit_registered: if not _atexit_registered:
# register once — atexit doesn't dedupe, so repeated queue re-setups would # register once — atexit doesn't dedupe; repeated re-setups would otherwise
# otherwise stack identical callbacks (harmless but unbounded) # stack identical callbacks
atexit.register(_stop_listener) atexit.register(_stop_listener)
_atexit_registered = True _atexit_registered = True
else: else:
@@ -258,7 +341,11 @@ def setup_logging(
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 setup-time warnings actually land in the
# configured log rather than being lost to stderr before any handler existed
_flush_warnings(warnings)
return root return root