3 Commits
Author SHA1 Message Date
LeoVasanko a4efbca55b Clarify diagnostic log messages; simplify describe_callback fallback
Unnamed callables (partials, callable instances) are described by type
name only: docstrings are shown only for named callables, avoiding
misleading class docstrings in failure messages.

Diagnostic messages revised for clarity when mixed with application
logs; logger.exception() messages no longer repeat the exception text,
which the traceback already shows.
2026-09-16 02:55:10 +00:00
LeoVasanko 44c1ed191e Configure kanta event loggers at import time, inheriting the root level.
configure_logging() now runs with default arguments when kanta.logging
is imported, attaching a plain stderr handler with propagate=False to
the event loggers (kanta.bootstrap/migration/transaction) that carry
Kanta-rendered output.  No levels are set by default, so event output
inherits the effective root level: a framework switching root between
INFO in development and WARNING in production governs Kanta output too.

Other configure_logging changes: channel enable flags use
logger.disabled (propagate toggling no longer silences now that event
loggers have their own handler), skiproot=False removes Kanta's
handler and re-enables propagation so the root logger renders event
output, and debug=True lifts only the DEBUG-emitting loggers
(bootstrap, migration) to DEBUG instead of setting a level on the
"kanta" parent.
2026-09-16 02:16:58 +00:00
LeoVasanko a41f34d332 Route all diagnostic logging through the plain "kanta" logger.
Module loggers used __name__, splitting diagnostics across eight
module-named loggers and colliding kanta.transaction with the
transaction event channel.  Diagnostics (integrity errors, flush
failures, rotation notes) are few; they now all go through the
"kanta" logger, following the application's root logging
configuration like any ordinary library output.
2026-09-16 02:16:58 +00:00
13 changed files with 194 additions and 114 deletions
+1
View File
@@ -174,6 +174,7 @@ def resolve_user_key(value: str) -> str | None:
- By default a transaction is logged with an `action by user` header followed by the diff lines. Added paths are colored green, deleted paths red. ANSI color codes are stripped after formatting when the standard error stream does not support color: `NO_COLOR` disables colors, `FORCE_COLOR` forces them, otherwise a tty check and a journald (`JOURNAL_STREAM`) check decide. The CLI (`python -m kanta`) strips its output the same way.
- `kanta.transaction(..., extra=...)` accepts a display-only value that is shown after the action in the header. Anything other than `None` is printed str-converted (colored by Kanta), unless a custom logemit handler does something else with it; it is never persisted in the `ChangeRecord`.
- `kanta.transaction(..., logdiff=False)` skips building and printing the diff body and logs only the header, which is useful for large or noisy changesets. Diff output can also be disabled globally with `configure_logging(diff=False)`; diff lines are emitted on the `kanta.transaction.diff` child logger so applications can route or silence them separately from the headers.
- The event loggers `kanta.bootstrap`, `kanta.migration` and `kanta.transaction` are configured at import time (via `configure_logging()`, callable again to change the toggles): a plain stderr handler with no prefix and `propagate = False`, since Kanta renders this output itself. No levels are set, so they inherit the effective root level — a framework switching root between INFO in development and WARNING in production governs Kanta output too. Operational diagnostics (integrity errors, flush failures, rotation notes) use the plain `kanta` logger instead, propagating to the root logger and following the application's normal logging configuration.
#### Log Emitters
+2 -7
View File
@@ -8,7 +8,6 @@ import contextlib
import importlib
import importlib.metadata
import importlib.util
import logging
import sys
import tempfile
from pathlib import Path
@@ -17,7 +16,7 @@ from typing import Any
import msgspec
from kanta import Kanta
from kanta.callbacks import InjectionContext
from kanta.callbacks import InjectionContext, callback_error_reporter
from kanta.exceptions import DatabaseError, DataIntegrityError, ReplayError
from kanta.grep import GrepPattern, evaluate
from kanta.logging import (
@@ -50,8 +49,6 @@ EXIT_PARSE_ERROR = 10
EXIT_MIGRATION_ERROR = 20
EXIT_VALIDATION_ERROR = 21
_logger = logging.getLogger(__name__)
def _print(*args: Any) -> None:
"""Print to stderr, stripping ANSI codes when the stream has no color support.
@@ -408,13 +405,11 @@ async def _log_migration(
"""
registry = kanta._impl.callback_registry
if registry.has("logmigr"):
try:
await registry.invoke(
"logmigr",
InjectionContext(kanta=kanta, report=result),
on_error=callback_error_reporter("logmigr"),
)
except Exception:
_logger.exception("logmigr callback failed")
return
if quiet:
return
+43 -6
View File
@@ -54,7 +54,40 @@ def _state_tag(ann: Any) -> str | None:
return None
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
def describe_callback(callback: Callable[..., Any]) -> str:
"""Return ``name (docstring first line)`` identifying *callback*.
Used in failure messages so a bare log line names the function that
failed, e.g. ``myformatter (Concise log formatter)``. Callables without
a ``__name__`` (partials, callable instances, ...) are described by
their type name only: less information, but never wrong information.
"""
name = getattr(callback, "__name__", None)
if not isinstance(name, str):
return type(callback).__name__
doc = inspect.getdoc(callback)
if doc:
return f"{name} ({doc.splitlines()[0]})"
return name
def callback_error_reporter(
kind: str,
) -> Callable[[Exception, Callable[..., Any]], None]:
"""Return an ``on_error`` reporter for :meth:`CallbackRegistry.invoke`.
The returned callable logs ``Kanta.<kind> <name (docstring)> failed``
with the traceback for each failing callback; invoke continues with
the rest.
"""
def _report(callback_error: Exception, callback: Callable[..., Any]) -> None:
_logger.exception("Kanta.%s %s failed", kind, describe_callback(callback))
return _report
class LogFmt:
@@ -245,12 +278,14 @@ class CallbackRegistry:
def build_logfmt(self, ctx: InjectionContext) -> Callable[[Any, str], str | None]:
"""Build a chained formatter from registered logfmt callbacks."""
formatters: list[tuple[Callable[[Any, str], str | None], str | None]] = []
formatters: list[
tuple[Callable[[Any, str], str | None], str | None, Callable[..., Any]]
] = []
for spec in self._logfmt_callbacks:
if isinstance(spec, _LogFmtClassSpec):
kwargs = self._build_kwargs(spec.inject_params, ctx)
instance: Callable[[Any, str], str | None] = spec.cls(**kwargs)
formatters.append((instance, spec.path))
formatters.append((instance, spec.path, spec.cls))
else:
kwargs = self._build_kwargs(spec.inject_params, ctx)
@@ -270,10 +305,10 @@ class CallbackRegistry:
return formatter
formatters.append((make_formatter(), spec.path))
formatters.append((make_formatter(), spec.path, spec.callback))
def format_value(value: Any, path: str) -> str | None:
for fn, pattern in formatters:
for fn, pattern, callback in formatters:
if pattern is not None and path != pattern:
continue
try:
@@ -281,7 +316,9 @@ class CallbackRegistry:
except Exception:
# Formatting must never break functionality; a failing
# callback is reported and treated as a fall-through.
_logger.exception("logfmt callback %r failed", fn)
_logger.exception(
"Kanta.logfmt %s failed", describe_callback(callback)
)
continue
if resolved is not None:
return resolved
+1 -1
View File
@@ -16,7 +16,7 @@ from pathlib import Path
from kanta.exceptions import FileLockError
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
def _fatal(msg: str, *, db_path: Path | None = None) -> None:
+3 -8
View File
@@ -10,7 +10,7 @@ from datetime import UTC, datetime, timedelta
from types import SimpleNamespace
from typing import Any, Generic, TypeVar
from kanta.callbacks import CallbackRegistry, InjectionContext
from kanta.callbacks import CallbackRegistry, InjectionContext, callback_error_reporter
from kanta.exceptions import DatabaseError, DataIntegrityError, ReplayError
from kanta.logging import (
_USER_PATH,
@@ -25,16 +25,11 @@ from kanta.rotation import execute_rotation, plan_rotation
from kanta.serialization import restore_data_in_place, struct_to_dict
from kanta.serialization.base import replay
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
T = TypeVar("T")
def _log_callback_error(callback_error, callback):
"""Report a failing logging callback and continue with the next one."""
_logger.exception("Log callback %r failed: %s", callback, callback_error)
class KantaImpl(PersistenceMixin, Generic[T]):
"""Internal state and logic for Kanta."""
@@ -119,7 +114,7 @@ class KantaImpl(PersistenceMixin, Generic[T]):
kanta=self._kanta,
report=report,
),
on_error=_log_callback_error,
on_error=callback_error_reporter("logmigr"),
)
return
+59 -26
View File
@@ -17,6 +17,7 @@ from typing import Any
import msgspec
from kanta.callbacks import describe_callback
from kanta.serialization.base import _apply, unmarshal
from kanta.tty import Line, displaywidth, strip_ansi, use_color
@@ -24,7 +25,17 @@ transaction_logger = logging.getLogger("kanta.transaction")
bootstrap_logger = logging.getLogger("kanta.bootstrap")
migration_logger = logging.getLogger("kanta.migration")
_logger = logging.getLogger(__name__)
# Event loggers carry Kanta-rendered content (colored headers, diffs) and are
# configured at import time; diagnostics from Kanta's internals use the plain
# "kanta" logger so they follow the application's root logging configuration.
EVENT_LOGGERS = ("kanta.bootstrap", "kanta.migration", "kanta.transaction")
# Loggers that emit DEBUG-level events (file-opened summary, migration diffs).
_DEBUG_LOGGERS = ("kanta.bootstrap", "kanta.migration")
_PLAIN_HANDLER_NAME = "kanta.plain"
_logger = logging.getLogger("kanta")
# Pattern to match control characters and bidirectional overrides
_UNSAFE_CHARS = re.compile(
@@ -148,13 +159,16 @@ def emit_event(
try:
proceed = handler(ev)
except Exception:
_logger.exception("logemit callback failed, using default formatting")
_logger.exception(
"Kanta.logemit %s failed, using default formatting",
describe_callback(handler),
)
break
if not proceed:
return
render(ev)
except Exception:
_logger.exception("failed to emit %s log event", ev.kind)
_logger.exception("Kanta failed to emit %s log event", ev.kind)
def _maybe_strip(text: str) -> str:
@@ -566,6 +580,15 @@ def log_change(
)
def _ensure_plain_handler(logger: logging.Logger) -> None:
"""Attach Kanta's no-prefix stderr handler to *logger* if it has none."""
if not logger.handlers:
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(logging.Formatter("%(message)s"))
handler.name = _PLAIN_HANDLER_NAME
logger.addHandler(handler)
def configure_logging(
*,
skiproot: bool = True,
@@ -577,13 +600,21 @@ def configure_logging(
) -> None:
"""Configure Kanta's default logging output.
Called once at import time with default arguments; call again to change
the toggles. The event loggers ``kanta.bootstrap``, ``kanta.migration``
and ``kanta.transaction`` carry Kanta-rendered output (colored headers,
diffs) and print it bare through a plain stderr handler with
``propagate = False``. Diagnostic messages use the plain ``kanta``
logger and follow the application's root logging configuration.
No levels are set by default: the event loggers inherit the effective
level of the root logger.
Args:
skiproot: If ``True`` (default), attach a no-prefix stderr handler to
the ``kanta`` logger and set ``kanta.propagate = False`` so Kanta
output is rendered directly without propagating to the root logger.
If ``False``, the child logger enable flags are still applied, but
no handler is added and ``kanta`` propagation is left untouched so
the application's root logger handles Kanta output.
skiproot: If ``True`` (default), event loggers print through Kanta's
own plain handler without propagating to the root logger. If
``False``, Kanta's handler is removed and propagation enabled so
the application's root logger renders event output instead.
bootstrap: Whether bootstrap logs are enabled.
migration: Whether migration logs are enabled.
transaction: Whether transaction logs are enabled.
@@ -591,13 +622,10 @@ def configure_logging(
only transaction headers are printed and diff formatting is
skipped. Per transaction this is controlled by the ``logdiff``
argument of :meth:`Kanta.transaction`.
debug: Whether to set the ``kanta`` logger level to ``DEBUG`` instead
of ``INFO``. This reveals debug-level output such as migration
diffs, which are hidden by default.
This helper is not called automatically; applications that want Kanta's
default output can call it, but most applications will configure logging
themselves.
debug: Whether to set the event loggers that emit DEBUG-level output
(bootstrap and migration) to ``DEBUG``, revealing output such as
the file-opened summary and migration diffs. ``False`` resets
them to inheriting the root level.
"""
logging.getLogger("kanta.transaction.diff").disabled = not diff
@@ -606,16 +634,21 @@ def configure_logging(
("kanta.migration", migration),
("kanta.transaction", transaction),
):
logging.getLogger(name).propagate = enabled
logging.getLogger(name).disabled = not enabled
if not skiproot:
return
for name in _DEBUG_LOGGERS:
logging.getLogger(name).setLevel(logging.DEBUG if debug else logging.NOTSET)
target = logging.getLogger("kanta")
target.propagate = False
for name in EVENT_LOGGERS:
logger = logging.getLogger(name)
if skiproot:
logger.propagate = False
_ensure_plain_handler(logger)
else:
logger.propagate = True
logger.handlers[:] = [
h for h in logger.handlers if h.name != _PLAIN_HANDLER_NAME
]
if not target.handlers:
handler = logging.StreamHandler(sys.stderr)
handler.setFormatter(logging.Formatter("%(message)s"))
target.addHandler(handler)
target.setLevel(logging.DEBUG if debug else logging.INFO)
configure_logging() # Import-time default setup; call again to reconfigure.
+6 -12
View File
@@ -12,7 +12,7 @@ from datetime import UTC, datetime
from pathlib import Path
from typing import Any
from kanta.callbacks import CallbackRegistry, InjectionContext
from kanta.callbacks import CallbackRegistry, InjectionContext, callback_error_reporter
from kanta.diff import diff
from kanta.exceptions import DatabaseError, DataIntegrityError
from kanta.filelock import LockedFile
@@ -21,7 +21,7 @@ from kanta.serialization import JsonSerializer, Serializer
from kanta.serialization.framing import Framer
from kanta.snapshot import SnapshotState
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
class PersistenceMixin:
@@ -110,20 +110,14 @@ class PersistenceMixin:
break
except DatabaseError as e:
self.background_error = e
def _log_callback_error(callback_error, callback):
_logger.exception(
"Background error callback %r failed: %s",
callback,
callback_error,
)
await self.callback_registry.invoke(
"fatal_error",
InjectionContext(error=e, kanta=self._kanta),
on_error=_log_callback_error,
on_error=callback_error_reporter("fatal_error"),
)
_logger.error(
"Kanta background flush failed; automatic flushing stopped: %s", e
)
_logger.error("Background flush loop stopped: %s", e)
break
def maybe_snapshot(self) -> None:
+3 -2
View File
@@ -20,7 +20,7 @@ from kanta.structs import ChangeRecord, Snapshot
from kanta.serialization.base import Serializer, apply_diff
from kanta.serialization.framing import Framer
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
@dataclass
@@ -216,7 +216,8 @@ def execute_rotation(
f.truncate(plan.cutoff_end)
if log:
_logger.info(
"rotated %s: kept %d change record(s), history before %s moved to %s",
"Rotated database %s: kept %d change record(s), "
"moved history before %s to %s",
path,
plan.retained_changes,
plan.rotated_ts.isoformat(),
+2 -2
View File
@@ -10,7 +10,7 @@ from kanta.structs import Snapshot
from kanta.serialization import JsonSerializer, Serializer
from kanta.serialization.framing import Framer, LineFramer
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
MINDIFFS = 100
@@ -69,7 +69,7 @@ class SnapshotState:
self._write(file, version, state, ts, m=m)
self._force_pending = False
except Exception as exc:
_logger.error("snapshot: failed to write snapshot: %r", exc)
_logger.error("Kanta snapshot failed: %r", exc)
def _write(
self, file, version: int, state: dict, now: datetime, m: datetime | None = None
+1 -1
View File
@@ -13,7 +13,7 @@ from kanta.callbacks import InjectionContext
from kanta.logging import _USER_PATH, LogEvent, emit_event, transaction_logger
from kanta.serialization import restore_data_in_place, struct_to_dict
_logger = logging.getLogger(__name__)
_logger = logging.getLogger("kanta")
def _build_logfmt(impl, previous: dict, current: dict):
+19
View File
@@ -1,3 +1,5 @@
import logging
import pytest
from kanta.serialization import JsonSerializer, MsgPackSerializer
@@ -12,3 +14,20 @@ from kanta.serialization import JsonSerializer, MsgPackSerializer
)
def format_config(request):
return request.param
@pytest.fixture(autouse=True)
def _kanta_event_loggers_propagate():
"""Let kanta's event loggers propagate so caplog captures their records.
Kanta configures them with ``propagate = False`` at import time, which
would hide their records from pytest's root-logger capture handler.
"""
names = ("kanta.bootstrap", "kanta.migration", "kanta.transaction")
loggers = [logging.getLogger(name) for name in names]
previous = [logger.propagate for logger in loggers]
for logger in loggers:
logger.propagate = True
yield
for logger, propagate in zip(loggers, previous):
logger.propagate = propagate
+19 -16
View File
@@ -38,13 +38,23 @@ def _reset_kanta_loggers():
logger.handlers.clear()
def _setup_logging(**kwargs):
"""Default kanta logging with the event loggers lifted to INFO.
Event loggers inherit the root level (WARNING under pytest); output
assertions need INFO.
"""
configure_logging(**kwargs)
for name in ("kanta.bootstrap", "kanta.migration", "kanta.transaction"):
logging.getLogger(name).setLevel(logging.INFO)
def _change_event(**kwargs) -> LogEvent:
return LogEvent(kind="change", logger=transaction_logger, action="update", **kwargs)
def test_emit_event_falsy_return_stops_chain(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
calls = []
def first(ev):
@@ -60,15 +70,13 @@ def test_emit_event_falsy_return_stops_chain(capsys):
def test_emit_event_truthy_return_falls_back_to_default(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
emit_event(_change_event(), [lambda ev: True])
assert "update" in capsys.readouterr().err
def test_emit_event_mutation_reaches_later_handlers_and_default(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
calls = []
def first(ev):
@@ -86,8 +94,7 @@ def test_emit_event_mutation_reaches_later_handlers_and_default(capsys):
def test_emit_event_handler_error_falls_back_to_default(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
def boom(ev):
raise RuntimeError("broken")
@@ -109,8 +116,7 @@ def test_diff_lines_built_lazily(monkeypatch):
def test_default_emit_created_and_migrated(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
emit_event(LogEvent(kind="created", logger=bootstrap_logger, filename="x.kantadb"))
emit_event(
LogEvent(
@@ -129,8 +135,7 @@ def test_default_emit_created_and_migrated(capsys):
def test_default_emit_strips_ansi_without_color_support(capsys, monkeypatch):
"""NO_COLOR output contains no ANSI codes; FORCE_COLOR keeps them."""
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
monkeypatch.setenv("NO_COLOR", "1")
monkeypatch.delenv("FORCE_COLOR", raising=False)
emit_event(_change_event(diff={"counter": 1}))
@@ -138,8 +143,7 @@ def test_default_emit_strips_ansi_without_color_support(capsys, monkeypatch):
assert "\x1b[" not in err
assert "counter" in err
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
monkeypatch.setenv("FORCE_COLOR", "1")
monkeypatch.delenv("NO_COLOR", raising=False)
emit_event(_change_event(diff={"counter": 1}))
@@ -357,8 +361,7 @@ async def test_event_carries_kanta_instance(tmp_path, format_config):
def test_header_is_settable_and_used_by_default_emit(capsys):
logging.getLogger("kanta").handlers.clear()
configure_logging()
_setup_logging()
def restyle(ev):
ev.header = f"CUSTOM {ev.action}"
+31 -29
View File
@@ -39,33 +39,42 @@ def _reset_kanta_loggers():
def test_configure_logging_defaults():
kanta_logger = logging.getLogger("kanta")
configure_logging()
assert kanta_logger.level == logging.INFO
assert not kanta_logger.propagate
assert kanta_logger.handlers
for name in ("kanta.bootstrap", "kanta.migration", "kanta.transaction"):
logger = logging.getLogger(name)
assert logger.level == logging.NOTSET # inherits the root level
assert not logger.propagate
assert logger.handlers
def test_configure_logging_disables_specific_loggers():
configure_logging(bootstrap=False, migration=False, transaction=False)
assert not logging.getLogger("kanta.bootstrap").propagate
assert not logging.getLogger("kanta.migration").propagate
assert not logging.getLogger("kanta.transaction").propagate
assert logging.getLogger("kanta.bootstrap").disabled
assert logging.getLogger("kanta.migration").disabled
assert logging.getLogger("kanta.transaction").disabled
def test_configure_logging_skiproot_false_leaves_kanta_propagation():
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging(bootstrap=False, skiproot=False)
assert kanta_logger.propagate
assert not kanta_logger.handlers
assert not logging.getLogger("kanta.bootstrap").propagate
def test_configure_logging_skiproot_false_routes_via_root():
configure_logging(skiproot=False)
for name in ("kanta.bootstrap", "kanta.migration", "kanta.transaction"):
logger = logging.getLogger(name)
assert logger.propagate
assert not logger.handlers
def _setup_logging(**kwargs):
"""Default kanta logging with the event loggers lifted to INFO.
Event loggers inherit the root level (WARNING under pytest); output
assertions need INFO.
"""
configure_logging(**kwargs)
for name in ("kanta.bootstrap", "kanta.migration", "kanta.transaction"):
logging.getLogger(name).setLevel(logging.INFO)
def test_log_change_no_diff(capsys):
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging()
_setup_logging()
log_change("test", {})
captured = capsys.readouterr()
assert "test" in captured.err
@@ -74,9 +83,7 @@ def test_log_change_no_diff(capsys):
def test_log_change_appends_extra_string(capsys, monkeypatch):
monkeypatch.setenv("FORCE_COLOR", "1")
monkeypatch.delenv("NO_COLOR", raising=False)
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging()
_setup_logging()
log_change("export", {}, extra="mydb.db")
captured = capsys.readouterr()
assert "export" in captured.err
@@ -84,9 +91,7 @@ def test_log_change_appends_extra_string(capsys, monkeypatch):
def test_log_change_log_diff_false(capsys, monkeypatch):
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging()
_setup_logging()
def _boom(*args, **kwargs):
raise AssertionError("format_diff should not be called")
@@ -99,9 +104,7 @@ def test_log_change_log_diff_false(capsys, monkeypatch):
def test_configure_logging_diff_false(capsys):
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging(diff=False)
_setup_logging(diff=False)
log_change("update", {"counter": 5}, previous={})
captured = capsys.readouterr()
assert "update" in captured.err
@@ -109,10 +112,9 @@ def test_configure_logging_diff_false(capsys):
def test_configure_logging_diff_true_reenables(capsys):
kanta_logger = logging.getLogger("kanta")
kanta_logger.handlers.clear()
configure_logging(diff=False)
_setup_logging(diff=False)
configure_logging(diff=True)
logging.getLogger("kanta.transaction").setLevel(logging.INFO)
log_change("update", {"counter": 5}, previous={})
captured = capsys.readouterr()
assert "counter" in captured.err