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

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

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

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 17:11:45 -04:00
dsql 73007fe900 feat: module_levels for per-logger level overrides at setup
add an optional module_levels={logger_name: level} param to setup_logging,
the ergonomic way to quiet noisy dependencies (motor/pymongo/aiohttp -> WARNING)
from the one entry-point call instead of scattering setLevel afterwards.

- exact logger-name match, no discovery; stdlib hierarchy applies so naming a
  parent quiets its subtree
- str or int level per entry, same normalization as root level
- bad level for one entry is skipped + warned, never raises (never-crash rule)
- module_levels=None/{} (default) is byte-identical to prior behavior

additive, backwards-compatible -> v0.3.0.

Signed-off-by: disqualifier <dev@disqualifier.me>
2026-06-29 03:40:55 -04:00
7 changed files with 164 additions and 20 deletions
+1 -1
View File
@@ -1,5 +1,5 @@
# claude # claude
CLAUDE.md .claude/
# python # python
__pycache__/ __pycache__/
+47 -3
View File
@@ -13,11 +13,13 @@ and emit; their records flow into the handlers `log_setup` wired.
## Install ## Install
``` ```
log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.2.0 log_setup @ git+ssh://git@git.rethinkstudios.io/rethink-public/log_setup.git@v0.3.2
``` ```
No dependencies — stdlib only. No dependencies — stdlib only.
Drop the `@v0.3.2` suffix from the line above to install the latest unpinned.
## Quick start ## Quick start
```python ```python
@@ -89,7 +91,8 @@ logging.getLogger("bot.core").info("ready", extra={"monitor": "heartbeat"})
setup_logging( setup_logging(
name="run", # base -> run.log (the live file at cwd) name="run", # base -> run.log (the live file at cwd)
log_dir="logs", # rotated/compressed copies live here (created if absent) log_dir="logs", # rotated/compressed copies live here (created if absent)
level="INFO", # root level (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)
rotate="daily", # "daily" | "size" | "on_start" | None rotate="daily", # "daily" | "size" | "on_start" | None
backup_count=14, # rotated files to keep (older auto-deleted) backup_count=14, # rotated files to keep (older auto-deleted)
max_bytes=10_000_000, # only for rotate="size" max_bytes=10_000_000, # only for rotate="size"
@@ -102,6 +105,47 @@ setup_logging(
) -> logging.Logger # returns the configured root logger ) -> 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`) ## Async-friendly (`queue=True`)
For async-heavy apps, `queue=True` routes records through a stdlib `QueueHandler` to a For async-heavy apps, `queue=True` routes records through a stdlib `QueueHandler` to a
@@ -135,4 +179,4 @@ color formatting, per-logger filters, remote handlers.
## Versioning ## Versioning
Tagged `vX.Y.Z`. Pin the tag. Releases are tagged `vX.Y.Z`. The install line above pins a release; drop the `@vX.Y.Z` suffix to install the latest unpinned. Pin deliberately for reproducible installs.
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project] [project]
name = "log_setup" name = "log_setup"
version = "0.2.0" version = "0.3.2"
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 = []
+1 -1
View File
@@ -19,4 +19,4 @@ from .setup import setup_logging
__all__ = ["setup_logging"] __all__ = ["setup_logging"]
__version__ = "0.2.0" __version__ = "0.3.2"
+11 -2
View File
@@ -15,6 +15,11 @@ DEFAULT_FORMAT = "%(asctime)s | %(name)s | %(levelname)s | %(message)s"
DEFAULT_DATEFMT = "%Y-%m-%d %H:%M:%S" DEFAULT_DATEFMT = "%Y-%m-%d %H:%M:%S"
_RESERVED = frozenset(vars(logging.makeLogRecord({})).keys()) | {"message", "asctime"} _RESERVED = frozenset(vars(logging.makeLogRecord({})).keys()) | {"message", "asctime"}
# this formatter's own canonical output keys — stdlib's LogRecord rejects `extra` keys
# colliding with real attribute names (e.g. `module`), but `time`/`level` are NOT
# LogRecord attrs, so a caller's extra={"time":...}/{"level":...} would otherwise
# overwrite the UTC timestamp / levelname. guard them explicitly
_OUTPUT_KEYS = frozenset({"time", "level", "module", "message"})
class JsonLinesFormatter(logging.Formatter): class JsonLinesFormatter(logging.Formatter):
@@ -38,10 +43,14 @@ class JsonLinesFormatter(logging.Formatter):
"message": record.getMessage(), "message": record.getMessage(),
} }
for key, value in record.__dict__.items(): for key, value in record.__dict__.items():
if key not in _RESERVED and not key.startswith("_"): if key not in _RESERVED and key not in _OUTPUT_KEYS and not key.startswith("_"):
payload[key] = value payload[key] = value
if record.exc_info: if record.exc_info:
payload["exc_info"] = self.formatException(record.exc_info) # cache the rendered traceback on the record (as stdlib Formatter does) so a
# second handler/format() of the same record doesn't re-render it
if not record.exc_text:
record.exc_text = self.formatException(record.exc_info)
payload["exc_info"] = record.exc_text
elif record.exc_text: elif record.exc_text:
payload["exc_info"] = record.exc_text payload["exc_info"] = record.exc_text
if record.stack_info: if record.stack_info:
+30 -4
View File
@@ -13,6 +13,25 @@ import time
from typing import Callable, Optional, Tuple from typing import Callable, Optional, Tuple
def _move(source: str, dest: str) -> None:
"""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
different filesystems — exactly the container bind-mount / separate-logs-volume
case this lib targets. fall back to shutil.move (copy+unlink) so the roll still
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
timestamped/dated dest). os.replace and shutil.move differ on a dest that already
exists as a directory, so this helper is not safe for arbitrary dests — only the
rotation paths that guarantee a fresh file dest.
"""
try:
os.replace(source, dest)
except OSError:
shutil.move(source, dest)
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
@@ -46,7 +65,7 @@ def make_rotator(
shutil.copyfileobj(src, dst) shutil.copyfileobj(src, dst)
os.remove(source) os.remove(source)
else: else:
os.replace(source, dest) _move(source, dest)
if log_dir is not None and prune_stem is not None: if 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
@@ -62,14 +81,21 @@ def rotate_on_start(live_path: str, log_dir: str, compress: bool, clock=time.loc
return return
stem = os.path.splitext(os.path.basename(live_path))[0] stem = os.path.splitext(os.path.basename(live_path))[0]
stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock()) stamp = time.strftime("%Y-%m-%d_%H-%M-%S", clock())
dest = os.path.join(log_dir, f"{stem}.{stamp}.log") suffix = ".log.gz" if compress 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
dest = os.path.join(log_dir, f"{stem}.{stamp}{suffix}")
counter = 1
while os.path.exists(dest):
dest = os.path.join(log_dir, f"{stem}.{stamp}.{counter}{suffix}")
counter += 1
if compress: if compress:
dest += ".gz"
with open(live_path, "rb") as src, gzip.open(dest, "wb") as dst: with open(live_path, "rb") as src, gzip.open(dest, "wb") as dst:
shutil.copyfileobj(src, dst) shutil.copyfileobj(src, dst)
os.remove(live_path) os.remove(live_path)
else: else:
os.replace(live_path, dest) _move(live_path, dest)
def prune(log_dir: str, stem: str, backup_count: int) -> None: def prune(log_dir: str, stem: str, backup_count: int) -> None:
+73 -8
View File
@@ -12,8 +12,8 @@ import atexit
import logging import logging
import logging.handlers import logging.handlers
import os import os
import queue import queue as _queue
from typing import Optional, Union from typing import Dict, Optional, Union
from .formats import build_formatter from .formats import build_formatter
from .rotation import attach_rolling, prune, rotate_on_start from .rotation import attach_rolling, prune, rotate_on_start
@@ -22,10 +22,15 @@ log = logging.getLogger(__name__)
_MARKER = "_log_setup_owned" _MARKER = "_log_setup_owned"
_listener = None _listener = None
_atexit_registered = False
def _level_value(level: Union[int, str]) -> int: def _level_value(level: Union[int, str]) -> int:
"""coerce a level name or int to a logging level int (defaults to INFO)""" """coerce a level name or int to a logging level int (defaults to INFO)"""
if isinstance(level, bool):
# bool is an int subclass (True==1, below DEBUG) but is never a real level —
# reject it consistently with the per-module path rather than set level 1
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):
@@ -36,11 +41,54 @@ def _level_value(level: Union[int, str]) -> int:
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]:
"""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
an invalid value as None so the per-module path can skip + warn rather than silently
apply INFO to a logger the caller named with a typo'd level
"""
if isinstance(level, bool):
return None
if isinstance(level, int):
return level
if not isinstance(level, str):
return None
resolved = logging.getLevelName(level.upper())
return resolved if isinstance(resolved, int) else None
def _apply_module_levels(module_levels: Optional[Dict[str, Union[int, str]]]) -> None:
"""set per-logger level overrides by exact logger name, never crashing
each name->level entry calls `logging.getLogger(name).setLevel(<level>)`. names are
matched exactly (no discovery); stdlib hierarchy still applies, so a parent name
quiets its whole subtree. a bad level for one entry is skipped with a warning so the
other entries and the rest of setup still proceed.
"""
if not module_levels:
return
for mod_name, raw_level in module_levels.items():
value = _strict_level_value(raw_level)
if value is None:
log.warning("log_setup: invalid level %r for logger %r; skipping", raw_level, mod_name)
continue
logging.getLogger(mod_name).setLevel(value)
def _clear_owned(root: logging.Logger) -> None: def _clear_owned(root: logging.Logger) -> None:
"""remove only the handlers this lib previously added; leave app handlers alone""" """remove only the handlers this lib previously added; leave app handlers alone"""
global _listener global _listener
if _listener is not None: if _listener is not None:
_listener.stop() _listener.stop()
# the listener owns the real file/console handlers (only the QueueHandler is
# root-attached + marked); stopping it doesn't close them, so close them here
# to avoid relying on GC finalizers across a re-setup
for wrapped in getattr(_listener, "handlers", ()):
try:
wrapped.close()
except Exception:
log.warning("log_setup: failed to close queued handler %r", wrapped, exc_info=True)
_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):
@@ -48,7 +96,9 @@ def _clear_owned(root: logging.Logger) -> None:
try: try:
handler.close() handler.close()
except Exception: except Exception:
pass # a handler failing to close must not abort re-setup, but log it
# rather than swallow silently (consistent with the lib's warn pattern)
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:
@@ -84,6 +134,7 @@ def setup_logging(
name: str = "run", name: str = "run",
log_dir: str = "logs", log_dir: str = "logs",
level: Union[int, str] = "INFO", level: Union[int, str] = "INFO",
module_levels: Optional[Dict[str, Union[int, str]]] = None,
rotate: Optional[str] = "daily", rotate: Optional[str] = "daily",
backup_count: int = 14, backup_count: int = 14,
max_bytes: int = 10_000_000, max_bytes: int = 10_000_000,
@@ -97,6 +148,15 @@ 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`. `name` -> <name>.log live file at cwd; rolled/compressed copies go to `log_dir`.
`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
to quiet noisy dependencies (e.g. {"motor": "WARNING", "aiohttp": "WARNING"}) from
the one setup call instead of scattering `getLogger(...).setLevel(...)` afterwards —
it's stdlib hierarchy under the hood, not new capability. names match EXACTLY (no
discovery: a typo'd name silently configures an unused logger), but stdlib hierarchy
applies, so naming a parent ("aiohttp") quiets its whole subtree (aiohttp.client,
aiohttp.access, ...). each entry accepts a str or int level; a bad value for one
entry is skipped with a warning and never aborts the others or the setup.
`rotate` is "daily" (default), "size", "on_start", or None. `console=True` adds a `rotate` is "daily" (default), "size", "on_start", or None. `console=True` adds a
stdout handler (off by default — the file is the output). `queue=True` routes records stdout handler (off by default — the file is the output). `queue=True` routes records
through a background QueueListener so file I/O never blocks the caller (the listener through a background QueueListener so file I/O never blocks the caller (the listener
@@ -109,10 +169,11 @@ def setup_logging(
unwritable `log_dir` falls back to console-only with a warning even when `console` is unwritable `log_dir` falls back to console-only with a warning even when `console` is
off, so output is never silently lost; an unknown `output` falls back to text. off, so output is never silently lost; an unknown `output` falls back to text.
""" """
global _listener global _listener, _atexit_registered
root = logging.getLogger() root = logging.getLogger()
root.setLevel(_level_value(level)) root.setLevel(_level_value(level))
_apply_module_levels(module_levels)
_clear_owned(root) _clear_owned(root)
formatter = build_formatter(output, fmt, datefmt) formatter = build_formatter(output, fmt, datefmt)
@@ -140,12 +201,16 @@ def setup_logging(
handlers.append(sh) handlers.append(sh)
if queue: if queue:
record_queue: "queue.Queue" = _make_queue() record_queue: "_queue.Queue" = _make_queue()
qh = _tag(logging.handlers.QueueHandler(record_queue)) qh = _tag(logging.handlers.QueueHandler(record_queue))
root.addHandler(qh) root.addHandler(qh)
_listener = logging.handlers.QueueListener(record_queue, *handlers, respect_handler_level=True) _listener = logging.handlers.QueueListener(record_queue, *handlers, respect_handler_level=True)
_listener.start() _listener.start()
atexit.register(_stop_listener) if not _atexit_registered:
# register once — atexit doesn't dedupe, so repeated queue re-setups would
# otherwise stack identical callbacks (harmless but unbounded)
atexit.register(_stop_listener)
_atexit_registered = True
else: else:
for handler in handlers: for handler in handlers:
root.addHandler(_tag(handler)) root.addHandler(_tag(handler))
@@ -156,9 +221,9 @@ def setup_logging(
return root return root
def _make_queue() -> "queue.Queue": def _make_queue() -> "_queue.Queue":
"""unbounded in-memory queue for the QueueHandler -> QueueListener path""" """unbounded in-memory queue for the QueueHandler -> QueueListener path"""
return queue.Queue(-1) return _queue.Queue(-1)
def _stop_listener() -> None: def _stop_listener() -> None: