docs: compress prose/module docstrings, em-dash->hyphen (de-bloat wave 1)

Signed-off-by: disqualifier <dev@disqualifier.me>
This commit is contained in:
2026-07-03 00:32:56 -04:00
parent 93994da9d6
commit 4d1acc3a47
6 changed files with 107 additions and 182 deletions
+2 -2
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.6.0 log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.1
``` ```
No dependencies — stdlib only. No dependencies — stdlib only.
Drop the `@v0.6.0` suffix from the line above to install the latest unpinned. Drop the `@v0.6.1` suffix from the line above to install the latest unpinned.
## Quick start ## Quick start
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project] [project]
name = "log_setup" name = "log_setup"
version = "0.6.0" version = "0.6.1"
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 = []
+3 -9
View File
@@ -1,8 +1,4 @@
"""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, optional
console output, and a consistent `time | module | level | message` format.
from log_setup import setup_logging from log_setup import setup_logging
@@ -10,13 +6,11 @@ console output, and a consistent `time | module | level | message` format.
log = logging.getLogger(__name__) log = logging.getLogger(__name__)
log.info("up") # -> run.log (add console=True for stdout too) 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 .setup import setup_logging from .setup import setup_logging
__all__ = ["setup_logging"] __all__ = ["setup_logging"]
__version__ = "0.6.0" __version__ = "0.6.1"
+11 -18
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,7 +13,7 @@ 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 # 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 # 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 # LogRecord attrs, so a caller's extra={"time":...}/{"ts":...} would otherwise overwrite
# the UTC timestamp / epoch. guard them explicitly # the UTC timestamp / epoch. guard them explicitly
@@ -26,14 +24,10 @@ 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/ts/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); `ts` (added v0.6.0) is the same instant as a suffix; `ts` is the same instant as a unix epoch int, both sortable across
unix epoch int (`int(record.created)`, second resolution) for a consumer that wants machines/containers. any field passed via logging `extra={...}` lands as a
a sortable number instead of parsing the ISO string — both sort unambiguously top-level JSON field. a traceback (exc_info) is rendered into an `exc_info`
across machines/containers; Grafana converts to local for display. any field string field rather than dropped.
passed via logging `extra={...}` lands as a top-level JSON field (how a caller
stamps monitor/service/request-id for Loki labels without the lib knowing those
domain concepts). a traceback (exc_info) is rendered into an `exc_info` string
field rather than dropped.
""" """
def format(self, record: logging.LogRecord) -> str: def format(self, record: logging.LogRecord) -> str:
@@ -49,8 +43,7 @@ class JsonLinesFormatter(logging.Formatter):
if key not in _RESERVED and key not in _OUTPUT_KEYS 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:
# cache the rendered traceback on the record (as stdlib Formatter does) so a # cache the rendered traceback on the record, like stdlib Formatter does
# second handler/format() of the same record doesn't re-render it
if not record.exc_text: if not record.exc_text:
record.exc_text = self.formatException(record.exc_info) record.exc_text = self.formatException(record.exc_info)
payload["exc_info"] = record.exc_text payload["exc_info"] = record.exc_text
@@ -66,9 +59,9 @@ def build_formatter(output: str = "text", fmt=None, datefmt=None) -> logging.For
`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.
""" """
if output == "json": if output == "json":
return JsonLinesFormatter() return JsonLinesFormatter()
+46 -63
View File
@@ -5,11 +5,12 @@ the namer/rotator so rolled files land in `log_dir` and are gzipped when asked,
the live file at its stable path, and handle the on-start and prune paths the handlers the live file at its stable path, and handle the on-start and prune 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 FOOTGUN: gzip writes are crash-safe - `_gzip_file` writes to a `.tmp` sibling and
`os.replace`s it onto the final `.gz` path, so a crash/OOM/power-loss mid-write never atomically `os.replace`s it onto the final `.gz` path, so a crash/OOM/power-loss
leaves a truncated `.gz` where retention would trust it. `retier`'s plain/gz dedupe mid-write never leaves a truncated `.gz` where retention would trust it. `retier`'s
additionally verifies a `.gz` decompresses cleanly (`_gz_intact`) before removing its plain/gz dedupe additionally verifies a `.gz` decompresses cleanly (`_gz_intact`)
plain twin, so a corrupt `.gz` is never preferred over an intact plain copy. before removing its plain twin, so a corrupt `.gz` is never preferred over an intact
plain copy.
""" """
import gzip import gzip
@@ -22,13 +23,10 @@ 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) across filesystems the container FOOTGUN: os.replace is atomic but raises OSError(EXDEV) across filesystems (the
bind-mount / separate-logs-volume case this lib targets. falls back to shutil.move container bind-mount / separate-logs-volume case) - falls back to shutil.move so
(copy+unlink) so the roll still lands instead of failing rotation silently. the roll still lands instead of failing rotation silently. precondition: `dest` is
a free, non-directory path.
precondition: `dest` is a free, non-directory path (every call site generates a
unique timestamped/dated dest) — not safe for arbitrary dests that may already
exist as a directory.
""" """
try: try:
os.replace(source, dest) os.replace(source, dest)
@@ -39,9 +37,8 @@ def _move(source: str, dest: str) -> None:
def _free_dest(dest: str) -> str: def _free_dest(dest: str) -> str:
"""return `dest`, or a `.N`-suffixed variant if it (or its .gz twin) already exists """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 used by the tiered rotator so a second same-stamp roll doesn't clobber the earlier
(two daily rolls in one day) doesn't clobber the earlier file. checks both the plain file; checks both the plain and .gz forms of each candidate.
and .gz forms of each candidate.
""" """
if not os.path.exists(dest) and not os.path.exists(dest + ".gz"): if not os.path.exists(dest) and not os.path.exists(dest + ".gz"):
return dest return dest
@@ -56,14 +53,14 @@ def _free_dest(dest: str) -> str:
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)
writes to `dest + ".tmp"` and atomically `os.replace`s it onto `dest` once FOOTGUN (crash-safe): writes to `dest + ".tmp"` and atomically `os.replace`s it
complete, so a crash/OOM/power-loss mid-write never leaves a truncated `.gz` at onto `dest` once complete, so a crash/OOM/power-loss mid-write never leaves a
`dest` the partial write stays quarantined in `.tmp` and source is untouched truncated `.gz` at `dest` - the partial write stays quarantined in `.tmp` and
(safe to retry). source is untouched (safe to retry).
the source mtime is carried onto dest so a file keeps its tier position when it 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 crosses the plain->gz boundary - a fresh write would otherwise make a
otherwise make a just-compressed file look newest and reshuffle tiers. just-compressed file look newest and reshuffle tiers.
""" """
mtime = _safe_mtime(source) mtime = _safe_mtime(source)
tmp_dest = dest + ".tmp" tmp_dest = dest + ".tmp"
@@ -88,9 +85,8 @@ def _gz_intact(path: str) -> bool:
"""return True if the gzip file at path decompresses cleanly end to end """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 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 .gz - a corrupt .gz must never be trusted over an intact plain copy. reads the
the whole stream (gzip.open only validates end-of-stream on a full read); any whole stream; any failure means "not intact" so the caller keeps the plain source.
failure is treated as "not intact" so the caller keeps the plain source.
""" """
try: try:
with gzip.open(path, "rb") as handle: with gzip.open(path, "rb") as handle:
@@ -121,8 +117,8 @@ def make_history_namer(
"""namer minting historic rolled files `<stem>.<Y-m-d_H-M-S>.log[.gz]` in log_dir """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 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 project namespace), independent of the live file's name. FOOTGUN: prune/retier's
glob this same stem or nothing matches and retention silently never fires. `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 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 daily) in favor of a uniform timestamped name so all modes converge on one shape
@@ -151,15 +147,15 @@ 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 only scans `backup_count` newest rolled files - the stdlib handler's own retention only scans
the live file's directory, so it never sees files redirected into `log_dir`; pruning the live file's directory, so it never sees files redirected into `log_dir`; pruning
here is what bounds retention for daily/size. FOOTGUN: `backup_count <= 0` means here is what bounds retention for daily/size. FOOTGUN: `backup_count <= 0` means
"keep no rolled history", but `prune()` itself no-ops at `<= 0` (its own sentinel for "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 "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. 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, next file PLAIN and re-tier `log_dir` - newest `keep_uncompressed` stay uncompressed, next
`keep_compressed` gzipped, rest deleted. `compress`/`backup_count` are ignored. `keep_compressed` gzipped, rest deleted. `compress`/`backup_count` are ignored.
""" """
tiered = keep_uncompressed is not None or keep_compressed is not None tiered = keep_uncompressed is not None or keep_compressed is not None
@@ -168,10 +164,8 @@ 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 roll # strip the namer's .gz suffix so the roll lands plain and retier decides
# lands plain and retier decides its tier. disambiguate a dest that already # its tier; disambiguate a same-interval collision via _free_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) 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:
@@ -207,7 +201,7 @@ def rotate_on_start(
tiered mode (`keep_uncompressed`/`keep_compressed` given): the rolled file always tiered mode (`keep_uncompressed`/`keep_compressed` given): the rolled file always
lands PLAIN (so it can occupy the newest uncompressed tier) and `retier` decides lands PLAIN (so it can occupy the newest uncompressed tier) and `retier` decides
compression/deletion across the whole stem `compress` is ignored here. 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
@@ -217,11 +211,9 @@ def rotate_on_start(
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 1-second stamp resolution means two starts in the same second collide; # a 1-second stamp collision (rapid crash-restart) is disambiguated with a
# disambiguate with a counter so a rapid crash-restart loop doesn't lose the # counter; check BOTH .log and .log.gz since a tiered same-stamp roll may
# earlier roll. check BOTH .log and .log.gz forms: in tiered mode an earlier # already be compressed
# 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")
@@ -248,7 +240,7 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
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 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 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 (e.g. "sub/run") must be matched by "run." here or nothing matches and retention
silently never fires (unbounded pileup). silently never fires (unbounded pileup).
@@ -266,10 +258,8 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
return return
entries = [os.path.join(log_dir, name) for name in names] entries = [os.path.join(log_dir, name) for name in names]
# dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove # dedupe plain/gz twins FIRST (a crash between _gzip_file's write and its os.remove
# can leave <x>.log beside <x>.log.gz) so the phantom twin never occupies a # can leave <x>.log beside <x>.log.gz), but ONLY once the .gz is verified intact -
# retention slot and evicts a distinct older roll — but ONLY once the .gz is # a pre-existing corrupt .gz must never win over an intact plain copy
# 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) present = set(entries)
kept = [] kept = []
for p in entries: for p in entries:
@@ -278,13 +268,12 @@ def retier(log_dir: str, stem: str, keep_uncompressed: int, keep_compressed: int
try: try:
os.remove(p) os.remove(p)
except OSError: except OSError:
kept.append(p) # couldn't remove keep it in the accounting kept.append(p) # couldn't remove - keep it in the accounting
continue continue
# .gz twin is corrupt keep the intact plain untouched; a later retier # .gz twin is corrupt - keep the intact plain, a later retier retries
# retries the compress once it's re-gzipped cleanly
kept.append(p) kept.append(p)
files = [(p, _safe_mtime(p), _roll_counter(p)) for p in kept if os.path.isfile(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) # newest-first: higher mtime first, ties broken by higher (later) roll counter
files.sort(key=lambda t: (t[1], t[2]), reverse=True) files.sort(key=lambda t: (t[1], t[2]), reverse=True)
keep = keep_uncompressed + keep_compressed keep = keep_uncompressed + keep_compressed
@@ -297,17 +286,14 @@ 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 # drop the redundant plain twin, but ONLY once the .gz is intact
# 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): if _gz_intact(dest):
try: try:
os.remove(path) os.remove(path)
except OSError: except OSError:
pass pass
continue continue
# .gz is corrupt fall through and re-gzip the plain over the bad dest # .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:
@@ -318,12 +304,9 @@ def _roll_counter(path: str) -> int:
"""parse the same-second disambiguation counter out of a rolled filename """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` 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 (optionally `.gz`); a higher counter is the later roll, first roll of a second is 0.
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>`) don't end in `.log`, so they never need
the tie-break - return 0 rather than misparsing the trailing date as a counter.
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 base = path[:-3] if path.endswith(".gz") else path
if not base.endswith(".log"): if not base.endswith(".log"):
@@ -337,11 +320,11 @@ 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 newest-first by mtime 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 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. 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 "sub/run") still matches the basenamed rolled files in log_dir - else nothing
matches and old files pile up forever. matches and old files pile up forever.
""" """
if backup_count <= 0: if backup_count <= 0:
@@ -380,9 +363,9 @@ def attach_rolling(
) -> 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), 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]` 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 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 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. and (for size) can't be managed once files are redirected into log_dir.
+44 -89
View File
@@ -1,15 +1,13 @@
"""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. called by the crashes the app over logging, and can route through a background queue so an async
APPLICATION, not by reusable libraries (those stay emit-only). idempotent (no event loop doesn't block on file I/O.
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 `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 of `backup_count`, including `backup_count=0` (means "keep zero rolled files", not
"never roll" each roll is deleted right after landing). "never roll" - each roll is deleted right after landing).
""" """
import atexit import atexit
@@ -32,21 +30,12 @@ _atexit_registered = False
def _exc_text() -> str: def _exc_text() -> str:
"""render sys.exc_info() as text, for capturing a traceback into a buffered warning """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() return "".join(traceback.format_exception(*sys.exc_info())).strip()
def _flush_warnings(warnings: list) -> None: def _flush_warnings(warnings: list) -> None:
"""emit buffered setup-time warnings now that handlers are attached """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: for message, *args in warnings:
log.warning(message, *args) log.warning(message, *args)
@@ -54,25 +43,19 @@ def _flush_warnings(warnings: list) -> None:
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):
# bool is an int subclass (True==1, below DEBUG) but is never a real level # bool is an int subclass (True==1, below DEBUG) but never a real level
# reject it consistently with the per-module path rather than set level 1
return logging.INFO 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` (falls back to INFO for the root `level`), reports invalid as
None so the per-module path can skip + warn instead of silently applying INFO
"""
if isinstance(level, bool): if isinstance(level, bool):
return None return None
if isinstance(level, int): if isinstance(level, int):
@@ -84,12 +67,7 @@ def _strict_level_value(level: Union[int, str]) -> Optional[int]:
def _apply_module_levels(module_levels: Optional[Dict[str, Union[int, str]]], warnings: list) -> 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"""
names match exactly (no discovery); stdlib hierarchy still applies, so a parent name
quiets its whole subtree. a bad level is skipped, its warning appended to `warnings`
(no handlers exist yet — see _flush_warnings) rather than emitted directly
"""
if not module_levels: if not module_levels:
return return
for mod_name, raw_level in module_levels.items(): for mod_name, raw_level in module_levels.items():
@@ -101,17 +79,12 @@ def _apply_module_levels(module_levels: Optional[Dict[str, Union[int, str]]], wa
def _clear_owned(root: logging.Logger, warnings: list) -> 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()
# listener owns the real file/console handlers (only QueueHandler is root- # listener owns the real file/console handlers; stopping it doesn't close
# attached + marked); stopping it doesn't close them, so close here rather than # them, so close here rather than rely 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()
@@ -138,10 +111,8 @@ def _tag(handler: logging.Handler) -> logging.Handler:
def _normalize_name(name: str) -> str: def _normalize_name(name: str) -> str:
"""strip one trailing '.log' (case-insensitive) so the stem is extension-free """strip one trailing '.log' (case-insensitive) so the stem is extension-free
`name` is allowed to be passed with or without the extension — "latest" and "latest" and "latest.log" both yield stem "latest" (never latest.log.log); only
"latest.log" both yield stem "latest" (live file latest.log), never latest.log.log. one level is stripped, so "app.log.log" -> "app.log".
only one level is stripped: "app.log.log" -> "app.log" so a legit ".log" inside a
name survives.
""" """
if name.lower().endswith(".log"): if name.lower().endswith(".log"):
return name[:-4] return name[:-4]
@@ -149,12 +120,7 @@ def _normalize_name(name: str) -> str:
def _history_stem() -> str: def _history_stem() -> str:
"""the project namespace for historic files: the cwd basename """the project namespace for historic files: the cwd basename, "" for a degenerate cwd"""
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: try:
return os.path.basename(os.getcwd().rstrip(os.sep)) return os.path.basename(os.getcwd().rstrip(os.sep))
except OSError: except OSError:
@@ -168,21 +134,14 @@ def _file_handler(
) -> 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 `name` is the LIVE stem; `history_stem` is the PROJECT stem that rolled/historic
rolled/historic files are named off + the retention glob keys on — decoupled: the files are named off, decoupled from the live file's own name.
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 # stdlib doRollover no-ops at backupCount==0 - force nonzero so the roll
# manage files redirected into log_dir — force nonzero so the roll always fires, # always fires; the REAL backup_count still flows to attach_rolling, whose
# and let attach_rolling's namer + retier/prune bound retention instead. the # make_rotator treats <=0 as "keep no rolled history" and deletes each roll
# 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) size_backup = max(backup_count, 1)
handler = logging.handlers.RotatingFileHandler( handler = logging.handlers.RotatingFileHandler(
live_path, maxBytes=max_bytes, backupCount=size_backup, encoding="utf-8", live_path, maxBytes=max_bytes, backupCount=size_backup, encoding="utf-8",
@@ -212,10 +171,10 @@ def _file_handler(
rotate_on_start(live_path, log_dir, compress, history_stem=history_stem) rotate_on_start(live_path, log_dir, compress, history_stem=history_stem)
prune(log_dir, history_stem, backup_count) prune(log_dir, history_stem, backup_count)
elif rotate is not None: elif rotate is not None:
# a typo'd value (e.g. "hourly") would otherwise silently fall through to a # a typo'd value would otherwise silently fall through to a non-rotating
# non-rotating FileHandler and grow forever warn instead of degrade silently # FileHandler and grow forever - warn instead of degrade silently
warnings.append(( warnings.append((
"log_setup: unknown rotate %r; expected 'daily'/'size'/'on_start'/None " "log_setup: unknown rotate %r; expected 'daily'/'size'/'on_start'/None - "
"no rotation applied (single growing file)", rotate, "no rotation applied (single growing file)", rotate,
)) ))
handler = logging.FileHandler(live_path, encoding="utf-8") handler = logging.FileHandler(live_path, encoding="utf-8")
@@ -248,8 +207,8 @@ def setup_logging(
`history_name` names the rolled/historic files (`<history_name>.<timestamp>.log[.gz]`), `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 independent of the live file: defaults to the PROJECT namespace = the cwd basename
(run from bestbuy/ -> historic files bestbuy.<stamp>...), settable explicitly. the (run from bestbuy/ -> historic files bestbuy.<stamp>...). the live file always keeps
live file always keeps `name`; only historic files carry the project name. `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
@@ -258,29 +217,28 @@ def setup_logging(
IGNORED in tiered mode. pass NEITHER knob and rotation behaves exactly as before. 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"}) from the one setup call to quiet noisy dependencies (e.g. {"motor": "WARNING"}) from one call instead of
instead of scattering `getLogger(...).setLevel(...)` afterwards (stdlib hierarchy scattering `getLogger(...).setLevel(...)` calls. names match EXACTLY (no discovery:
under the hood, not new capability). names match EXACTLY (no discovery: a typo'd a typo'd name silently configures an unused logger), but hierarchy applies, so
name silently configures an unused logger), but hierarchy applies, so naming a naming a parent ("aiohttp") quiets its whole subtree. str or int per entry; a bad
parent ("aiohttp") quiets its whole subtree. str or int per entry; a bad value is value is skipped with a warning and never aborts the others or the setup.
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. for `rotate="size"`, the
live file always rolls at `max_bytes` regardless of `backup_count`: `backup_count=0` live file always rolls at `max_bytes` regardless of `backup_count`: `backup_count=0`
means "keep zero rolled files" (each roll lands then is deleted immediately), NOT means "keep zero rolled files" (each roll lands then is deleted immediately), NOT
"disable rotation". `backup_count>=1` keeps that many rolled files as before. "disable rotation". `backup_count>=1` keeps that many rolled files as before.
`console=True` adds a stdout handler (off by default the file is the output). `console=True` adds a stdout handler (off by default - the file is the output).
`queue=True` routes records through a background QueueListener so file I/O never `queue=True` routes records through a background QueueListener so file I/O never
blocks the caller (stopped at exit). `output` is "text" (default, human `time | blocks the caller (stopped at exit). `output` is "text" (default, human `time |
module | level | message`, local time) or "json" (structured JSON Lines for the module | level | message`, local time) or "json" (structured JSON Lines, UTC
Grafana/Loki path, UTC timestamps + a unix-epoch `ts`, `extra=` fields surfaced as timestamps + a unix-epoch `ts`, `extra=` fields surfaced as top-level keys); file
top-level keys); file and console use the same format, live-file name unaffected. and console use the same format, live-file name unaffected. `fmt`/`datefmt` apply
`fmt`/`datefmt` apply to text output only. to text output only.
idempotent: a repeat call clears only the handlers this function added. never 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 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. warning even when `console` is off; an unknown `output` falls back to text.
""" """
global _listener, _atexit_registered global _listener, _atexit_registered
@@ -295,9 +253,8 @@ def setup_logging(
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, # history_name if given, else the cwd basename; falls back to the live stem for a
# else the cwd basename. normalized + basenamed like `name`; falls back to the live # degenerate cwd so naming/retention never break
# stem for a degenerate cwd so naming/retention never break.
history_source = history_name if history_name is not None else _history_stem() history_source = history_name if history_name is not None else _history_stem()
history_stem = os.path.basename(_normalize_name(history_source)) or stem history_stem = os.path.basename(_normalize_name(history_source)) or stem
@@ -332,8 +289,7 @@ 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; repeated re-setups would otherwise # register once - atexit doesn't dedupe, repeated re-setups would stack
# stack identical callbacks
atexit.register(_stop_listener) atexit.register(_stop_listener)
_atexit_registered = True _atexit_registered = True
else: else:
@@ -343,8 +299,7 @@ def setup_logging(
if not file_ok: if not file_ok:
warnings.append(("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 # flush now that handlers are attached, so warnings land in the configured log
# configured log rather than being lost to stderr before any handler existed
_flush_warnings(warnings) _flush_warnings(warnings)
return root return root