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>
This commit is contained in:
2026-07-02 23:30:01 -04:00
parent 8bf1866ca2
commit 93994da9d6
6 changed files with 252 additions and 224 deletions
+31 -12
View File
@@ -13,12 +13,12 @@ and emit; their records flow into the handlers `log_setup` wired.
## Install
```
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.5.1
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.6.0
```
No dependencies — stdlib only.
Drop the `@v0.5.1` suffix from the line above to install the latest unpinned.
Drop the `@v0.6.0` suffix from the line above to install the latest unpinned.
## Quick start
@@ -92,6 +92,7 @@ are deleted past the count. If instead you want the recent logs **uncompressed**
without `zcat`) and older ones **gzipped**, pass the two tier knobs:
```python
# app run from bestbuy/run.py , with name="latest":
setup_logging(
name="latest",
rotate="on_start", # works for on_start, daily, and size
@@ -100,13 +101,15 @@ setup_logging(
)
```
Result in `log_dir` (newest → oldest):
Result — the live file stays at its stable path in cwd; `log_dir` (default `logs/`) holds
the tiered historic files, named off the project stem (newest → oldest):
```
latest.log <- live "latest" (stable, tail -f)
latest.<t1>.log latest.<t2>.log latest.<t3>.log <- 3 newest: plain
latest.<t4>.log.gz ... latest.<t10>.log.gz <- next 7: gzipped
(anything past 10 deleted)
./latest.log <- live (stable, tail -f, in cwd)
logs/
bestbuy.<t1>.log bestbuy.<t2>.log bestbuy.<t3>.log <- 3 newest: plain
bestbuy.<t4>.log.gz ... bestbuy.<t10>.log.gz <- next 7: gzipped
(anything past 10 deleted)
```
- Each restart (`on_start`) or roll (`daily`/`size`) moves the live file into `log_dir`,
@@ -136,17 +139,22 @@ Promtail glob, bind-mount path, or your `tail` command.
```python
setup_logging(name="run", output="json")
logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"})
# -> {"time": "2026-06-28T14:03:11Z", "level": "INFO", "module": "bot.core",
# "message": "ready", "monitor": "heartbeat"}
# -> {"time": "2026-06-28T14:03:11Z", "ts": 1782151391, "level": "INFO",
# "module": "bot.core", "message": "ready", "monitor": "heartbeat"}
```
- **Fields:** `time`, `level`, `module`, `message` always; any `extra={...}` keys land
as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels — the lib
stays domain-agnostic); error records carry the traceback in `exc_info` (never dropped).
- **Fields:** `time`, `ts`, `level`, `module`, `message` always; any `extra={...}` keys
land as **top-level** fields (stamp `monitor`/`service`/request-id for Loki labels —
the lib stays domain-agnostic); error records carry the traceback in `exc_info` (never
dropped).
- **Time is UTC ISO-8601 with a `Z`** (`2026-06-28T14:03:11Z`), not local. json is the
aggregation path — logs from many servers/containers sort unambiguously only in UTC;
Grafana converts to local for display. (Text mode stays local — that's a human on one
box.)
- **`ts` (added v0.6.0)** is the same instant as a unix epoch integer
(`int(record.created)`, second resolution) alongside `time` — for a consumer that wants
a sortable number instead of parsing the ISO string. Additive: existing `time` is
unchanged, and a consumer that ignores unknown JSON keys is unaffected.
- Both file and console use the chosen format. `fmt`/`datefmt` apply to text only (json
builds fields, not a format string). An unknown `output` falls back to text + warns,
never crashes. **Zero new deps** — stdlib `json` only.
@@ -247,6 +255,17 @@ setup_logging(name="run", queue=True)
plain twin — a corrupt `.gz` (from before this fix, or an external cause) is never
preferred over an intact plain copy; the plain is kept and the `.gz` gets rewritten
cleanly on the next retier pass instead of being deleted.
- **Setup-time warnings reach the log file (v0.6.0+).** Previously, a warning raised
during `setup_logging` itself (an invalid `module_levels` entry, a handler failing to
close on re-setup, an unknown `rotate` value) was emitted *before* any handler was
attached, so it only reached stderr via logging's `lastResort` fallback and never
`run.log`. As of v0.6.0 these are buffered and flushed once the handlers are attached,
so they land in the configured log like any other record.
- **JSON output gained a `ts` field (v0.6.0, additive).** Alongside the existing `time`
(UTC ISO-8601, unchanged), each JSON line now also carries `ts`: the same instant as a
unix epoch integer (`int(record.created)`, second resolution) — for a consumer that
wants a sortable number instead of parsing the ISO string. Purely additive: `time` is
byte-for-byte unchanged, and a consumer that ignores unknown JSON keys is unaffected.
## Scope — what this is NOT