292 lines
16 KiB
Markdown
292 lines
16 KiB
Markdown
# log_setup
|
|
|
|
Stdlib, sync, **zero-dependency** logging setup an application calls **once** at its
|
|
entry point: a live `run.log`, rotation (daily / size / on-start), gzip of rolled
|
|
files, retention, console output, and a consistent `time | module | level | message`
|
|
format.
|
|
|
|
It **configures** logging (handlers, rotation, format) — which reusable libraries here
|
|
must never do. That's fine because `log_setup` is the *application's* entry-point
|
|
setup, not library-internal config. Libraries still only `logging.getLogger(__name__)`
|
|
and emit; their records flow into the handlers `log_setup` wired.
|
|
|
|
## Install
|
|
|
|
```
|
|
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.2
|
|
```
|
|
|
|
No dependencies — stdlib only.
|
|
|
|
Drop the `@v0.6.2` suffix from the line above to install the latest unpinned.
|
|
|
|
## Quick start
|
|
|
|
```python
|
|
import logging
|
|
from log_setup import setup_logging
|
|
|
|
setup_logging(name="run", level="INFO") # daily rotation, logs/ dir, gzip (file only)
|
|
|
|
log = logging.getLogger(__name__)
|
|
log.info("started") # -> ./run.log (add console=True for stderr too)
|
|
```
|
|
|
|
Call it once, at the app's entry point — before the rest of the app runs. Every module
|
|
(yours and the libraries you import) then just does `logging.getLogger(__name__)` and
|
|
emits; the records land in the configured root.
|
|
|
|
## What you get
|
|
|
|
- **Live file** at a stable path: `./run.log` — always `tail -f run.log`, no dated name
|
|
to chase. Rolled/compressed copies go into `log_dir` (default `logs/`).
|
|
- **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.
|
|
- **Rotation** (`rotate=`):
|
|
- `"daily"` (default) — rolls at midnight into `log_dir`, keeps `backup_count` days.
|
|
- `"size"` — rolls at `max_bytes` into `log_dir`, keeps `backup_count`. `backup_count=0`
|
|
means **keep no rolled history**: the live file still rolls at `max_bytes` (size is
|
|
always bounded), each rolled file is deleted immediately after landing — it does not
|
|
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.
|
|
- **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
|
|
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 stderr in the same format — opt in when
|
|
you want live terminal output alongside the file.
|
|
|
|
The `name` you pass is normalized so it produces exactly one `.log`: `name="latest"` and
|
|
`name="latest.log"` both yield the live file `latest.log` (never `latest.log.log`).
|
|
|
|
## Historic files are named off the project (`history_name`)
|
|
|
|
The **live** file keeps its defined `name` (`latest.log`). The **historic** (rolled/gz)
|
|
files are named off the **project namespace** — by default the current directory's basename
|
|
— so you can tell at a glance which service a log came from:
|
|
|
|
```python
|
|
# app run from bestbuy/run.py , with name="latest":
|
|
setup_logging(name="latest", rotate="daily")
|
|
# logs/
|
|
# latest.log <- live (the tail -f target)
|
|
# bestbuy.2026-07-01_02-00-00.log <- historic, named off the project dir
|
|
# bestbuy.2026-06-30_02-00-00.log.gz
|
|
```
|
|
|
|
- **Default** = `os.path.basename(os.getcwd())` (the project directory). Zero config.
|
|
- Override with **`history_name="foo"`** → historic files become `foo.<timestamp>.log[.gz]`.
|
|
- This changed in **v0.5.0**: historic files used to reuse the live `name`. To keep the old
|
|
behavior, pass `history_name=name`.
|
|
- Retention (tier counts / `backup_count`) is unchanged — it's just keyed to the project
|
|
stem now.
|
|
|
|
## Tiered retention (`keep_uncompressed` / `keep_compressed`)
|
|
|
|
The default is a flat `backup_count`: every rolled file is gzipped on roll and the oldest
|
|
are deleted past the count. If instead you want the recent logs **uncompressed** (read them
|
|
without `zcat`) and older ones **gzipped**, pass the two tier knobs:
|
|
|
|
```python
|
|
# app run from bestbuy/run.py , with name="latest":
|
|
setup_logging(
|
|
name="latest",
|
|
rotate="on_start", # works for on_start, daily, and size
|
|
keep_uncompressed=3, # newest 3 rolled logs kept PLAIN
|
|
keep_compressed=7, # next 7 kept GZIPPED; total retained = 10
|
|
)
|
|
```
|
|
|
|
Result — the live file stays at its stable path in cwd; `log_dir` (default `logs/`) holds
|
|
the tiered historic files, named off the project stem (newest → oldest):
|
|
|
|
```
|
|
./latest.log <- live (stable, tail -f, in cwd)
|
|
logs/
|
|
bestbuy.<t1>.log bestbuy.<t2>.log bestbuy.<t3>.log <- 3 newest: plain
|
|
bestbuy.<t4>.log.gz ... bestbuy.<t10>.log.gz <- next 7: gzipped
|
|
(anything past 10 deleted)
|
|
```
|
|
|
|
- Each restart (`on_start`) or roll (`daily`/`size`) moves the live file into `log_dir`,
|
|
then re-tiers: newest `keep_uncompressed` stay plain, the next `keep_compressed` are
|
|
gzipped in place, the rest deleted. Total kept = `keep_uncompressed + keep_compressed`.
|
|
- **Opt-in by presence** — pass either knob to enable tiering. Pass **neither** and
|
|
rotation behaves exactly as before (`backup_count` + gzip-on-roll), so existing callers
|
|
are unaffected.
|
|
- In tiered mode `backup_count` and the gzip-on-roll behavior of `compress` are **ignored**
|
|
— the tier counts bound retention instead.
|
|
- `keep_uncompressed=0` → everything gzipped; `keep_compressed=0` → only the plain tier.
|
|
Retention is count-based (not time-based).
|
|
|
|
## Output format (`output=`)
|
|
|
|
Two formats, two needs. Default is `"text"`; the live-file name is the same either way
|
|
(`run.log`, never auto-renamed), so a service can switch text↔json without breaking the
|
|
Promtail glob, bind-mount path, or your `tail` command.
|
|
|
|
- **`output="text"`** (default) — human-readable
|
|
`2026-06-27 19:55:05 | module.name | INFO | message`, **local time**. The
|
|
single-machine `tail -f` path. `fmt`/`datefmt` override it. Unchanged from v0.1.x.
|
|
- **`output="json"`** — structured **one JSON object per line** (JSON Lines) for the
|
|
Grafana/Loki pipeline (Promtail → Loki → Grafana); Loki parses JSON fields into labels
|
|
natively, no regex.
|
|
|
|
```python
|
|
setup_logging(name="run", output="json")
|
|
logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"})
|
|
# -> {"time": "2026-06-28T14:03:11Z", "ts": 1782151391, "level": "INFO",
|
|
# "module": "bot.core", "message": "ready", "monitor": "heartbeat"}
|
|
```
|
|
|
|
- **Fields:** `time`, `ts`, `level`, `module`, `message` always; any `extra={...}` keys
|
|
land as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels —
|
|
the lib stays domain-agnostic); error records carry the traceback in `exc_info` (never
|
|
dropped).
|
|
- **Time is UTC ISO-8601 with a `Z`** (`2026-06-28T14:03:11Z`), not local. json is the
|
|
aggregation path — logs from many servers/containers sort unambiguously only in UTC;
|
|
Grafana converts to local for display. (Text mode stays local — that's a human on one
|
|
box.)
|
|
- **`ts` (added v0.6.0)** is the same instant as a unix epoch integer
|
|
(`int(record.created)`, second resolution) alongside `time` — for a consumer that wants
|
|
a sortable number instead of parsing the ISO string. Additive: existing `time` is
|
|
unchanged, and a consumer that ignores unknown JSON keys is unaffected.
|
|
- Both file and console use the chosen format. `fmt`/`datefmt` apply to text only (json
|
|
builds fields, not a format string). An unknown `output` falls back to text + warns,
|
|
never crashes. **Zero new deps** — stdlib `json` only.
|
|
|
|
## Signature
|
|
|
|
```python
|
|
setup_logging(
|
|
name="run", # base -> run.log (the live file at cwd)
|
|
log_dir="logs", # rotated/compressed copies live here (created if absent)
|
|
level="INFO", # root level everything inherits (str name or logging constant)
|
|
module_levels=None, # {logger_name: level} per-logger overrides (exact name match)
|
|
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)
|
|
keep_uncompressed=None, # tiered: newest N rolled logs kept PLAIN (opt-in)
|
|
keep_compressed=None, # tiered: next M rolled logs kept GZIPPED (opt-in)
|
|
max_bytes=10_000_000, # only for rotate="size"
|
|
compress=True, # gzip rolled files
|
|
console=False, # also log to stderr (off by default; opt in)
|
|
queue=False, # route through a background QueueListener (async-friendly)
|
|
output="text", # "text" (human, local time) | "json" (structured, UTC)
|
|
fmt=None, # override the text format string (text mode only)
|
|
datefmt=None, # override the text date format (text mode only)
|
|
) -> logging.Logger # returns the configured root logger
|
|
```
|
|
|
|
## Quieting noisy dependencies (`module_levels`)
|
|
|
|
`level` is the **root default** — every logger inherits it. `module_levels` is an
|
|
optional `{logger_name: level}` map of **per-logger overrides** applied at setup, the
|
|
standard "turn down the chatty dependency while my own code stays at INFO" case:
|
|
|
|
```python
|
|
setup_logging(
|
|
name="run",
|
|
level="INFO", # our code logs at INFO
|
|
module_levels={
|
|
"motor": "WARNING", # quiet the driver
|
|
"pymongo": "WARNING",
|
|
"aiohttp": "WARNING", # also quiets aiohttp.client / aiohttp.access (hierarchy)
|
|
},
|
|
)
|
|
```
|
|
|
|
- **Exact-name match — names are NOT discovered.** It calls
|
|
`logging.getLogger(name).setLevel(level)` for exactly the name you give. There's no
|
|
smart find of noisy modules; you name the loggers. A typo (`"moter"`) silently
|
|
configures a logger nothing uses — no error, no effect. Get the names right.
|
|
- **Hierarchy applies** (the one "smart" part, and it's just stdlib): naming a **parent**
|
|
quiets its whole subtree. `"aiohttp"` also quiets `aiohttp.client`, `aiohttp.access`,
|
|
etc. — the way to catch sub-loggers without listing each.
|
|
- **str or int** per entry (`"WARNING"` or `logging.WARNING`) — same normalization as the
|
|
root `level`.
|
|
- **Never crashes:** a bad level for one entry is **skipped with a warning**; the other
|
|
entries and the rest of setup still apply. Consistent with the never-crash-over-logging
|
|
rule.
|
|
- `None`/`{}` (default) → no overrides; existing callers are unaffected.
|
|
|
|
Common noisy library logger names: `motor`, `pymongo`, `aiohttp` (parent quiets
|
|
`aiohttp.client`/`aiohttp.access`), `discord` / `discord.*`, `asyncio`, `urllib3`. Check
|
|
a lib's *actual* logger name — some log under a name different from their package.
|
|
|
|
This already works without the lib (`logging.getLogger("motor").setLevel(WARNING)` after
|
|
setup does the same via stdlib hierarchy). The param's value is ergonomic: it keeps the
|
|
overrides in the **one** `setup_logging` call at the entry point instead of scattering
|
|
`setLevel` calls afterward — which is the whole point of `log_setup`.
|
|
|
|
## Async-friendly (`queue=True`)
|
|
|
|
For async-heavy apps, `queue=True` routes records through a stdlib `QueueHandler` to a
|
|
background `QueueListener` that owns the file/console handlers, so the event loop never
|
|
blocks on file I/O. The API stays sync (`log.info()` as usual); the queue is internal.
|
|
The listener is stopped (and flushed) cleanly at process exit, so no records are lost.
|
|
|
|
```python
|
|
setup_logging(name="run", queue=True)
|
|
```
|
|
|
|
## Safety
|
|
|
|
- **Idempotent:** calling `setup_logging` again clears only the handlers it added (no
|
|
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
|
|
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.
|
|
- **`"daily"` regression fixed (v0.6.2).** v0.5.1's `rotate="size"` fix above shared its
|
|
rotator with `"daily"`, so a `rotate="daily", backup_count=0` roll was incorrectly
|
|
deleted at every midnight rollover instead of just landing unpruned. The rotator is now
|
|
rotate-mode aware: the zero-retention delete only ever fires for `"size"`, matching the
|
|
contract in the bullet above — `"daily"`/`"on_start"` with `backup_count=0` were always
|
|
meant to roll without pruning and now do again.
|
|
- **Gzip 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
|
|
|
|
`log_setup` produces clean, rotating, compressed, retention-managed, consistently
|
|
formatted **files**. It does **not** ship logs anywhere — no Loki/ELK/syslog/network
|
|
handlers. Getting files to a backend is a separate concern (e.g. Promtail tails
|
|
`run.log` → Loki → Grafana panels + alerting). Keeping shipping out means the log
|
|
backend can change without touching any app, and the consistent format here is what
|
|
makes downstream parsing and alerting easy.
|
|
|
|
Structured/JSON output is **in** as of v0.2.0 (`output="json"`) — text and json only.
|
|
Still deliberately out: logfmt or other formats, a format DSL, per-handler formats,
|
|
color formatting, per-logger filters, remote handlers.
|
|
|
|
## Versioning
|
|
|
|
Releases are tagged `vX.Y.Z`. The install line above pins a release; drop the `@vX.Y.Z` suffix to install the latest unpinned. Pin deliberately for reproducible installs.
|