From 7cb967770e1ea910342f51799fbc7dab19b43f3c Mon Sep 17 00:00:00 2001 From: didericis Date: Wed, 24 Jun 2026 15:37:57 -0400 Subject: [PATCH] feat(log): add leveled severity and structured context to log wrappers log.py was bare print-to-stderr wrappers with no levels or attributable context (issue #252). Add: - Ordered severities (debug/info/warn/error) gated by BOT_BOTTLE_LOG_LEVEL (default info). debug is silent by default; error always surfaces (nothing sits above it), so the fatal die path stays visible regardless of configured level. - An optional `context` mapping on every wrapper, rendered as a parseable ` [k=v ...]` suffix (keys sorted; whitespace/quoted values quoted) so failures can be filtered and correlated. Default output with no context is byte-identical to the original lines, so the 100+ existing single-string call sites are unaffected. Wires the supervise crash path (the example the issue names) to attach error_type and crash_log context. Adds test_log.py (backward-compat, context rendering, level gating, die surfacing). Closes #252. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01YcU7nerbg8cVj9R4EkpfLJ --- bot_bottle/cli/supervise.py | 5 +- bot_bottle/log.py | 106 +++++++++++++++++++++++++++--- tests/unit/test_log.py | 127 ++++++++++++++++++++++++++++++++++++ 3 files changed, 227 insertions(+), 11 deletions(-) create mode 100644 tests/unit/test_log.py diff --git a/bot_bottle/cli/supervise.py b/bot_bottle/cli/supervise.py index 5d6bf3a..fb76958 100644 --- a/bot_bottle/cli/supervise.py +++ b/bot_bottle/cli/supervise.py @@ -292,7 +292,10 @@ def cmd_supervise(argv: list[str]) -> int: return e.code if isinstance(e.code, int) else 1 except Exception as e: # noqa: W0718 — catch supervise crash for logging log_path = _write_crash_log(e) - error(f"supervise crashed: {type(e).__name__}: {e}") + error( + f"supervise crashed: {type(e).__name__}: {e}", + context={"error_type": type(e).__name__, "crash_log": str(log_path)}, + ) error(f"full traceback written to {log_path}") return 1 return 0 diff --git a/bot_bottle/log.py b/bot_bottle/log.py index b7d4204..65021eb 100644 --- a/bot_bottle/log.py +++ b/bot_bottle/log.py @@ -1,21 +1,107 @@ -"""Tiny logging wrappers. All output goes to stderr.""" +"""Tiny logging wrappers. All output goes to stderr. + +Two capabilities layer onto the bare wrappers (issue #252): + + - **Levels.** `debug` / `info` / `warn` / `error` carry an ordered + severity. Output is gated by `BOT_BOTTLE_LOG_LEVEL` (debug | info | + warn | error; default `info`). A message emits when its severity is + at or above the threshold, so `debug` is silent by default and + `error` always surfaces (nothing sits above it) — which keeps the + fatal `die` path visible regardless of the configured level. + + - **Context.** Every wrapper takes an optional `context` mapping that + renders as a parseable ` [k=v ...]` suffix (keys sorted; values with + whitespace/quotes are quoted), so failures can be filtered and + correlated instead of being flat strings. + +With no `context` and the default level, output is byte-identical to the +original `bot-bottle: ` / `bot-bottle: warning: ` / +`bot-bottle: error: ` lines — the 100+ existing call sites are +unaffected. +""" from __future__ import annotations +import os import sys -from typing import NoReturn +from typing import Mapping, NoReturn + +# Ordered severities. Gaps left between values so intermediate levels +# can be added later without renumbering. +DEBUG = 10 +INFO = 20 +WARN = 30 +ERROR = 40 + +_LEVEL_NAMES: dict[str, int] = { + "debug": DEBUG, + "info": INFO, + "warn": WARN, + "warning": WARN, + "error": ERROR, +} + +# Default threshold when BOT_BOTTLE_LOG_LEVEL is unset or unrecognised. +_DEFAULT_THRESHOLD = INFO + +_LOG_LEVEL_ENV = "BOT_BOTTLE_LOG_LEVEL" -def info(msg: str) -> None: - print(f"bot-bottle: {msg}", file=sys.stderr) +def _threshold() -> int: + """Resolve the active level threshold from the environment. + + Read per-call (not cached) so the level can be changed at runtime + and so tests can patch `os.environ` without a reload. Unknown values + fall back to the default rather than raising — logging must never be + the thing that crashes the process.""" + raw = os.environ.get(_LOG_LEVEL_ENV, "") + return _LEVEL_NAMES.get(raw.strip().lower(), _DEFAULT_THRESHOLD) -def warn(msg: str) -> None: - print(f"bot-bottle: warning: {msg}", file=sys.stderr) +def _format_context(context: Mapping[str, object] | None) -> str: + """Render a context mapping as a ` [k=v k2=v2]` suffix. + + Keys are sorted for stable, diffable output. Values that are empty or + contain whitespace or a quote are wrapped in double quotes (with inner + quotes escaped) so each `k=v` pair stays parseable. Empty/None context + renders as the empty string.""" + if not context: + return "" + parts: list[str] = [] + for key in sorted(context): + value = str(context[key]) + if value == "" or any(ch.isspace() for ch in value) or '"' in value: + value = '"' + value.replace('"', '\\"') + '"' + parts.append(f"{key}={value}") + return " [" + " ".join(parts) + "]" -def error(msg: str) -> None: - print(f"bot-bottle: error: {msg}", file=sys.stderr) +def _emit( + level: int, + label: str, + msg: str, + context: Mapping[str, object] | None, +) -> None: + if level < _threshold(): + return + prefix = f"{label}: " if label else "" + sys.stderr.write(f"bot-bottle: {prefix}{msg}{_format_context(context)}\n") + + +def debug(msg: str, *, context: Mapping[str, object] | None = None) -> None: + _emit(DEBUG, "debug", msg, context) + + +def info(msg: str, *, context: Mapping[str, object] | None = None) -> None: + _emit(INFO, "", msg, context) + + +def warn(msg: str, *, context: Mapping[str, object] | None = None) -> None: + _emit(WARN, "warning", msg, context) + + +def error(msg: str, *, context: Mapping[str, object] | None = None) -> None: + _emit(ERROR, "error", msg, context) class Die(SystemExit): @@ -31,6 +117,6 @@ class Die(SystemExit): self.message = message -def die(msg: str) -> NoReturn: - error(msg) +def die(msg: str, *, context: Mapping[str, object] | None = None) -> NoReturn: + error(msg, context=context) raise Die(1, msg) diff --git a/tests/unit/test_log.py b/tests/unit/test_log.py new file mode 100644 index 0000000..742c01c --- /dev/null +++ b/tests/unit/test_log.py @@ -0,0 +1,127 @@ +"""Unit: leveled + structured logging wrappers (issue #252). + +Locks three properties of bot_bottle.log: + - backward compatibility — default output is byte-identical to the + original bare wrappers, so the 100+ existing single-string call + sites are unaffected; + - context rendering — an optional mapping becomes a parseable + ` [k=v ...]` suffix; + - level gating — BOT_BOTTLE_LOG_LEVEL filters by severity, debug is + silent by default, and error always surfaces. +""" + +from __future__ import annotations + +import contextlib +import io +import unittest +from typing import Callable +from unittest import mock + +from bot_bottle import log + + +def _capture( + fn: Callable[..., None], + *args: object, + env: dict[str, str] | None = None, + **kwargs: object, +) -> str: + buf = io.StringIO() + patched = mock.patch.dict("os.environ", env or {}, clear=False) + with patched, contextlib.redirect_stderr(buf): + fn(*args, **kwargs) + return buf.getvalue() + + +class TestBackwardCompat(unittest.TestCase): + """No context + default level → exactly the legacy lines.""" + + def test_info(self): + self.assertEqual("bot-bottle: hello\n", _capture(log.info, "hello")) + + def test_warn(self): + self.assertEqual( + "bot-bottle: warning: careful\n", _capture(log.warn, "careful") + ) + + def test_error(self): + self.assertEqual( + "bot-bottle: error: boom\n", _capture(log.error, "boom") + ) + + +class TestContext(unittest.TestCase): + def test_appends_sorted_parseable_suffix(self): + out = _capture( + log.error, "rpc failed", context={"slug": "abc123", "code": "-32603"} + ) + # keys sorted: code before slug + self.assertEqual( + "bot-bottle: error: rpc failed [code=-32603 slug=abc123]\n", out + ) + + def test_quotes_values_with_whitespace(self): + out = _capture( + log.info, "did thing", context={"path": "/a b/c", "ok": "yes"} + ) + self.assertEqual( + 'bot-bottle: did thing [ok=yes path="/a b/c"]\n', out + ) + + def test_empty_context_is_noop_suffix(self): + self.assertEqual( + "bot-bottle: x\n", _capture(log.info, "x", context={}) + ) + + +class TestLevels(unittest.TestCase): + def test_debug_silent_by_default(self): + self.assertEqual("", _capture(log.debug, "trace")) + + def test_debug_emits_when_level_lowered(self): + out = _capture(log.debug, "trace", env={"BOT_BOTTLE_LOG_LEVEL": "debug"}) + self.assertEqual("bot-bottle: debug: trace\n", out) + + def test_error_level_suppresses_info_and_warn(self): + env = {"BOT_BOTTLE_LOG_LEVEL": "error"} + self.assertEqual("", _capture(log.info, "i", env=env)) + self.assertEqual("", _capture(log.warn, "w", env=env)) + # error still surfaces — nothing sits above it + self.assertEqual( + "bot-bottle: error: e\n", _capture(log.error, "e", env=env) + ) + + def test_unknown_level_falls_back_to_default(self): + # garbage value → default INFO threshold, so info still prints + out = _capture(log.info, "i", env={"BOT_BOTTLE_LOG_LEVEL": "loud"}) + self.assertEqual("bot-bottle: i\n", out) + + def test_warning_alias_accepted(self): + env = {"BOT_BOTTLE_LOG_LEVEL": "warning"} + self.assertEqual("", _capture(log.info, "i", env=env)) + self.assertEqual( + "bot-bottle: warning: w\n", _capture(log.warn, "w", env=env) + ) + + +class TestDie(unittest.TestCase): + def test_die_still_raises_and_prints_error(self): + buf = io.StringIO() + with contextlib.redirect_stderr(buf): + with self.assertRaises(log.Die) as cm: + log.die("fatal thing") + self.assertEqual("fatal thing", cm.exception.message) + self.assertIn("bot-bottle: error: fatal thing", buf.getvalue()) + + def test_die_surfaces_even_at_error_level(self): + buf = io.StringIO() + with mock.patch.dict("os.environ", {"BOT_BOTTLE_LOG_LEVEL": "error"}): + with contextlib.redirect_stderr(buf): + with self.assertRaises(log.Die): + log.die("still fatal") + self.assertIn("bot-bottle: error: still fatal", buf.getvalue()) + + +if __name__ == "__main__": + unittest.main() -- 2.52.0