From 3074f8d8b099962b11fc2b07ae6bf38f4a731ddf Mon Sep 17 00:00:00 2001 From: Leo Vasanko <2+leovasanko@git> Date: Fri, 7 Aug 2026 17:08:28 +0100 Subject: [PATCH] Implement richer, fully customizable logging; customizable timestamps (#1) - `@kanta.logemit` handler for completely customizable logging output, with `LogEvent` structure and `kanta.tty.Line` helper to create colorized text and fixed width fields - `configure_logging(diff=False)` to disable diff display globally (supplementing per-transaction `logdiff=False`) - `transaction(extra: Any = ...)` for passing extra strings or custom metadata to logs - `@kanta.clock` to provide user controlled clock for deterministic database outputs - Added a demo script that shows basic functions, migrations, logfmt etc. --- demo/.gitignore | 1 + demo/main.py | 110 ++++++++++ docs/database.md | 94 +++++++++ kanta/callbacks.py | 40 +++- kanta/kanta.py | 66 +++++- kanta/kantaimpl.py | 93 +++++--- kanta/logging.py | 289 ++++++++++++++++++++----- kanta/persistence.py | 47 ++++- kanta/snapshot.py | 21 +- kanta/transaction.py | 83 ++++++-- kanta/tty.py | 181 ++++++++++++++++ tests/test_clock.py | 135 ++++++++++++ tests/test_format_diff.py | 26 +++ tests/test_kanta_integration.py | 20 ++ tests/test_logemit.py | 362 ++++++++++++++++++++++++++++++++ tests/test_logging.py | 72 ++++++- tests/test_tty.py | 74 +++++++ 17 files changed, 1587 insertions(+), 127 deletions(-) create mode 100644 demo/.gitignore create mode 100644 demo/main.py create mode 100644 kanta/tty.py create mode 100644 tests/test_clock.py create mode 100644 tests/test_logemit.py create mode 100644 tests/test_tty.py diff --git a/demo/.gitignore b/demo/.gitignore new file mode 100644 index 0000000..74df5b7 --- /dev/null +++ b/demo/.gitignore @@ -0,0 +1 @@ +demo.kantadb diff --git a/demo/main.py b/demo/main.py new file mode 100644 index 0000000..1bdb436 --- /dev/null +++ b/demo/main.py @@ -0,0 +1,110 @@ +#!/usr/bin/env -S uv run +import asyncio +import sys +from datetime import UTC, datetime, timedelta +from pathlib import Path + +import msgspec + +from kanta import Kanta +from kanta.callbacks import DictPre +from kanta.logging import configure_logging + + +filename = Path(__file__).with_name("demo.kantadb") + +# For demonstration purposes, we use "original v0" and "modified v1" in this same script +# Normally your app would only have the latest supported data model + + +class Data(msgspec.Struct): # type: ignore - intentionally redefined later + users: dict[str, dict] = {} + counter: int = 0 + + +kanta_v0 = Kanta(filename, Data()) + + +@kanta_v0.bootstrap +def bootstrap(data: Data) -> None: + """Create the initial admin user.""" + data.users["userid001"] = {"name": "Alice", "role": "admin"} + + +# Redefinition to simulate new version +class Data(msgspec.Struct): + users: dict[str, dict] = {} + total: int = 0 # Replaces old counter field + lang: str = "en" # New field + + +def migrate_v1(d: dict) -> None: + """Rename counter to total""" + d["total"] = d["counter"] + + +kanta_v1 = Kanta(filename, Data(), migrations=sys.modules[__name__]) + + +@kanta_v1.logfmt +def resolve_user(value: str, path: str, previous: DictPre) -> str | None: + """Resolve user ids to names from the database state itself.""" + if path != "$user" and not path.startswith("users."): + return None + return previous.get("users", {}).get(value, {}).get("name") + + +async def main() -> None: + filename.unlink(missing_ok=True) + + print("# Database creation with v0 schema and basic ops, pretty logs") + # Open and close automatically; you can also `await kanta.open()` instead + async with kanta_v0 as kanta: + with kanta.transaction(action="create", user="userid001") as data: + data.users["userid002"] = {"name": "Bob", "role": "user"} + + with kanta.transaction(action="update", user="userid001") as data: + data.users["userid002"]["role"] = "editor" + data.counter = 1 + + # Display-only extra string, appended after the action. + with kanta.transaction( + action="export", user="userid002", extra="extra info" + ) as data: + data.counter = 2 + + print( + "\n# A later version of our application with new data model, migrations and logfmt" + ) + async with kanta_v1 as kanta: + with kanta.transaction( + action="update", user="userid002", extra=filename.name + ) as data: + data.total += 1 + + try: + with kanta.transaction(action="reset", user="userid001") as data: + data.total = 99 + raise ValueError("simulated failure") + except ValueError: + print(f"# Reading does not need transaction: {data.total=}", flush=True) + + with kanta.transaction(action="delete", user="userid002") as data: + del data.users["userid001"] + + +# Fake clock for deterministic timestamps +_now = datetime(2027, 1, 1, tzinfo=UTC) + + +@kanta_v0.clock +@kanta_v1.clock +def fake_clock() -> datetime: + global _now + _now += timedelta(hours=1) + return _now + + +if __name__ == "__main__": + configure_logging() + asyncio.run(main()) diff --git a/docs/database.md b/docs/database.md index 6c5765b..5b2cb58 100644 --- a/docs/database.md +++ b/docs/database.md @@ -163,6 +163,17 @@ when they have a default value. - Multiple handlers are supported and invoked in registration order. A failing handler is logged and does not prevent subsequent handlers from running. +#### Clock + +- `@kanta.clock` registers a callback `() -> datetime` that replaces the + default UTC clock. Its value is used for all record timestamps (`ts`, and + `m` when `mtime` is `True`) and for snapshot timestamps. +- The clock is only read when a timestamp is actually produced; no-op + transactions and skipped snapshot checks do not read it. +- Register before `open()` so that bootstrap and migration records use the + custom clock as well. This is mainly useful for tests and reproducible + demos. + #### Transaction Log Formatting - Logfmt callbacks prettify identifiers in the change log and are registered with @@ -197,6 +208,89 @@ def resolve_user_key(value: str) -> str | None: return names_by_id.get(value) ``` +#### Transaction Log Headers + +- 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. +- `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. + +#### Log Emitters + +- Every change-related message Kanta emits (transaction/bootstrap/migration + changes, `Created `, migration summaries, aborted transactions) is + described by a `kanta.logging.LogEvent` and dispatched through + `kanta.logging.emit_event`. Kanta's own output goes through the same + mechanism: when no `logemit` callback handles an event, + `kanta.logging.default_emit` renders it with the built-in formatting. +- A `LogEvent` carries the event `kind` (`"change"`, `"created"`, + `"migrated"`, `"aborted"`), the preferred `logger` and `level`, the + `kanta` instance, and all relevant state: `action`, `user`, `extra`, + `error` (for aborted transactions), `diff`, `previous`/`current` state + dicts, the built `logfmt` chain, and version info for migration events. + Application-specific context (e.g. a connection id) can be stored in + `kanta.ctx` — a user-writable namespace — and read back in callbacks as + `event.kanta.ctx`, which also covers creation/bootstrap events. +- The built-in formatting is assembled from standard blocks that custom + emitters can reuse as-is or replace piecemeal: + - `event.header` — a lazy property producing the default one-line header + for any kind: `[ ][ by ]` for changes, + `[ ][ by ] transaction aborted: ` for aborts, + and the + plain `Created`/`Migrated` summaries. It is settable: assign + `event.header = ...` and return truthy to restyle the header while + keeping the default diff routing. + - `event.diff_lines` — a lazy property producing the pretty diff body for + change events (built only if accessed). + - `default_emit` itself is just `header` plus the `diff_lines` routing. +- `@kanta.logemit` registers a callback receiving the event. The callback + decides what is logged and where: it may log one or more messages on + `event.logger`, log somewhere else, or nothing at all. A falsy return + value marks the event handled and stops the chain; a truthy return value + passes the event — possibly modified — to the next registered callback. + When all callbacks pass, `default_emit` renders the event; a callback may + also call `default_emit(event)` itself to delegate events it does not + customize. Operational diagnostics (integrity errors, background flush + failures) do not go through this mechanism. +- Logging never breaks functionality: a crashing `logemit` callback is + reported with `logger.exception` and the event falls back to the built-in + formatting; if the built-in formatting itself fails, the error is reported + and swallowed. The same applies to `logfmt` callbacks (a failing one is + treated as a fall-through) and `logmigr` callbacks. + +```python +@kanta.logemit +def emit(ev: LogEvent): + if ev.kind != "change": + return default_emit(ev) # delegate, no chaining needed + # Restyle the header; default_emit keeps routing the diff body. + ev.header = str(Line().user(ev.user or "-", width=20)(" ").action(ev.action)) + return True +``` + +#### Terminal Formatting Helpers + +- `kanta.tty` provides the building blocks used by Kanta's own rendering: + - `colors`: the mutable color palette. Colors are bare SGR parameter + strings (e.g. `"1;34"`, `"38;5;226"`) without escape framing. Attributes + are read at render time, so assignments (`colors.action = "36"`) and + additions (`colors.session = "38;5;226"`) take effect immediately. + - `Line`: builds a terminal string part by part. Calling it appends + content (`str`-converted); `.` arms a palette color for the + next call only, and the reset is folded into a single escape sequence + with whatever color comes next. `width=`/`align=` pad by display width; + `str(line)` finishes the line and restores default colors. + - `strip_ansi`, `displaywidth` (wide chars and emoji count correctly) and + `pad` for working with pre-colored strings. + ## Migrations - Migration source is configured on `Kanta(...)` via `migrations=`. diff --git a/kanta/callbacks.py b/kanta/callbacks.py index ef82271..034e997 100644 --- a/kanta/callbacks.py +++ b/kanta/callbacks.py @@ -7,11 +7,16 @@ default value. Log formatters are a special case: they are called per value being rendered and receive the value plus an optional ``path`` string. They return ``str | None``; ``None`` means "fall through to the next formatter". + +Log emitters (``logemit``) are another special case: plain callables that +receive a :class:`kanta.logging.LogEvent` and are dispatched by +:func:`kanta.logging.emit_event`. """ from __future__ import annotations import inspect +import logging import types from collections.abc import Callable from dataclasses import dataclass @@ -23,6 +28,8 @@ from kanta.migrations import MigrationResult DictPre = Annotated[dict, "pre"] DictPost = Annotated[dict, "post"] +_logger = logging.getLogger(__name__) + class LogFmt: """Base class for stateful logfmt callbacks. @@ -103,6 +110,7 @@ class CallbackRegistry: "logmigr": [], } self._logfmt_callbacks: list[_LogFmtFunctionSpec | _LogFmtClassSpec] = [] + self._logemit_callbacks: list[Callable[..., Any]] = [] def register( self, @@ -123,6 +131,14 @@ class CallbackRegistry: ) return callback + if kind == "logemit": + if inspect.isclass(callback) or not callable(callback): + raise TypeError("logemit callbacks must be functions") + if inspect.iscoroutinefunction(callback): + raise TypeError("logemit callbacks must not be async") + self._logemit_callbacks.append(callback) + return callback + if kind not in self._callbacks: raise ValueError(f"unknown callback kind: {kind}") @@ -175,8 +191,15 @@ class CallbackRegistry: """Return True if any callback of *kind* is registered.""" if kind == "logfmt": return bool(self._logfmt_callbacks) + if kind == "logemit": + return bool(self._logemit_callbacks) return bool(self._callbacks[kind]) + @property + def logemit_handlers(self) -> list[Callable[..., Any]]: + """Registered logemit callbacks in registration order.""" + return self._logemit_callbacks + 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]] = [] @@ -210,7 +233,13 @@ class CallbackRegistry: for fn, pattern in formatters: if pattern is not None and path != pattern: continue - resolved = fn(value, path) + try: + resolved = fn(value, path) + 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) + continue if resolved is not None: return resolved return None @@ -454,7 +483,12 @@ class CallbackRegistry: if self._data_type is not None and bare is self._data_type: return kind == "bootstrap" if self._kanta_class is not None and bare is self._kanta_class: - return kind in {"bootstrap", "fatal_error", "logfmt", "logmigr"} + return kind in { + "bootstrap", + "fatal_error", + "logfmt", + "logmigr", + } return False def _allowed_message(self, kind: str) -> str: @@ -462,7 +496,7 @@ class CallbackRegistry: if kind == "bootstrap": if self._data_type is not None: parts.append(self._data_type.__name__) - if kind in {"bootstrap", "fatal_error", "logfmt"}: + if kind in {"bootstrap", "fatal_error", "logfmt", "logmigr"}: if self._kanta_class is not None: parts.append(self._kanta_class.__name__) if kind == "fatal_error": diff --git a/kanta/kanta.py b/kanta/kanta.py index 963f308..6eca545 100644 --- a/kanta/kanta.py +++ b/kanta/kanta.py @@ -5,7 +5,7 @@ import logging from datetime import datetime from pathlib import Path from types import ModuleType, SimpleNamespace -from typing import Generic, TypeVar +from typing import Any, Generic, TypeVar from kanta.kantaimpl import KantaImpl from kanta.serialization import JsonSerializer, Serializer @@ -130,7 +130,10 @@ class Kanta(Generic[T]): """User-writable context namespace. Migration functions receive the ``Kanta`` instance and can read or - mutate ``kanta.ctx`` during migrations. + mutate ``kanta.ctx`` during migrations. Applications can also store + arbitrary data here (e.g. a connection id); since + :class:`kanta.logging.LogEvent` carries the Kanta instance, logemit + callbacks can read it as ``event.kanta.ctx``. """ return self._impl.ctx @@ -253,6 +256,27 @@ class Kanta(Generic[T]): return _register return _register(fn) + def clock(self, fn=None): + """Register a clock callback replacing the default UTC clock. + + Can be used as ``@kanta.clock``. The callback takes no arguments and + must return a :class:`~datetime.datetime`; its value is used for all + record timestamps (``ts``, and ``m`` when ``mtime`` is ``True``) and + snapshot timestamps. The clock is only read when a timestamp is + actually produced, so read-count-dependent clocks (e.g. advancing on + every read) stay deterministic. Register before :meth:`open` so that + bootstrap and migration records use the custom clock as well. This is + mainly useful for tests and reproducible demos. + """ + + def _register(callback): + self._impl.add_clock(callback) + return callback + + if fn is None: + return _register + return _register(fn) + def logmigr(self, fn=None): """Register a migration logging callback. @@ -292,13 +316,39 @@ class Kanta(Generic[T]): return _register return _register(fn) + def logemit(self, fn=None): + """Register a log emitter callback. + + Can be used as ``@kanta.logemit``. The callback receives a single + :class:`kanta.logging.LogEvent` describing the event, including the + preferred logger and level, and decides what (if anything) is logged + and where. + + A falsy return value marks the event as handled and stops the chain. + A truthy return value passes the event — possibly modified — to the + next registered callback; when all callbacks pass, Kanta renders the + event with its built-in formatting + (:func:`kanta.logging.default_emit`), which a callback may also call + itself to delegate events it does not care about. + """ + + def _register(callback): + self._impl.add_logemit(callback) + return callback + + if fn is None: + return _register + return _register(fn) + def transaction( self, action: str, *, user: str | None = None, + extra: Any = None, mtime: bool | datetime = True, log: bool | logging.Logger = True, + logdiff: bool = True, ): """Create a transactional mutation context manager. @@ -307,6 +357,11 @@ class Kanta(Generic[T]): user: Optional user identifier stored in metadata and rendered in the log header. Register a ``@kanta.logfmt`` callback to format the user value; the path ``"$user"`` is passed for this case. + extra: Optional display-only value shown after the action in the + log header. Anything other than ``None`` is printed + str-converted (colored by Kanta), unless a custom + ``@kanta.logemit`` handler does something else with it. It is + never persisted in the change record. mtime: Controls the modification time ``m``. ``True`` (default) sets ``m`` to the current UTC time. ``False`` omits ``m`` so the previous modification time remains in effect; this is used for @@ -317,6 +372,11 @@ class Kanta(Generic[T]): ``kanta.transaction`` logger. ``False`` suppresses the transaction log. A :class:`~logging.Logger` instance writes output to that logger instead. + logdiff: Whether to build and print the diff body. ``False`` + skips diff formatting entirely 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)``. Returns: A context manager yielding the live state object for mutation. @@ -330,6 +390,8 @@ class Kanta(Generic[T]): self._impl, action, user=user, + extra=extra, mtime=mtime, log=log, + logdiff=logdiff, ) diff --git a/kanta/kantaimpl.py b/kanta/kantaimpl.py index ea6495a..7888ba5 100644 --- a/kanta/kantaimpl.py +++ b/kanta/kantaimpl.py @@ -12,7 +12,13 @@ from typing import Any, Generic, TypeVar from kanta.callbacks import CallbackRegistry, InjectionContext from kanta.exceptions import DatabaseError, DataIntegrityError, ReplayError -from kanta.logging import _USER_PATH, bootstrap_logger, log_change, migration_logger +from kanta.logging import ( + _USER_PATH, + LogEvent, + bootstrap_logger, + emit_event, + migration_logger, +) from kanta.migrations import MigrationResult, Migrations from kanta.persistence import PersistenceMixin from kanta.serialization import restore_data_in_place, struct_to_dict @@ -23,6 +29,11 @@ _logger = logging.getLogger(__name__) 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.""" @@ -80,6 +91,10 @@ class KantaImpl(PersistenceMixin, Generic[T]): """Register one migration logging callback.""" self.callback_registry.register("logmigr", callback) + def add_logemit(self, callback) -> None: + """Register one log emitter callback.""" + self.callback_registry.register("logemit", callback) + async def _handle_migration_log( self, migration_result: MigrationResult, @@ -96,6 +111,7 @@ class KantaImpl(PersistenceMixin, Generic[T]): kanta=self._kanta, migration_result=migration_result, ), + on_error=_log_callback_error, ) return @@ -110,21 +126,31 @@ class KantaImpl(PersistenceMixin, Generic[T]): for info in changed: if info.diff: - log_change( - info.name, - info.diff, - previous=info.before, - logger=migration_log, - level=logging.DEBUG, + emit_event( + LogEvent( + kind="change", + logger=migration_log, + level=logging.DEBUG, + kanta=self._kanta, + action=info.name, + diff=info.diff, + previous=info.before, + ), + self.callback_registry.logemit_handlers, ) descriptions = [f"{m.name} ({m.description})" for m in changed] - migration_log.info( - "Migrated %s v%s -> v%s: %s", - self.filename, - previous_version, - migration_result.version, - ", ".join(descriptions), + emit_event( + LogEvent( + kind="migrated", + logger=migration_log, + kanta=self._kanta, + filename=str(self.filename), + from_version=previous_version, + to_version=migration_result.version, + migrations=descriptions, + ), + self.callback_registry.logemit_handlers, ) async def open( @@ -255,7 +281,11 @@ class KantaImpl(PersistenceMixin, Generic[T]): self.snapshot.request_force() await self.flush() self.snapshot.maybe_write( - self.file, self.version, self.statedict, m=self.mtime + self.file, + self.version, + self.statedict, + m=self.mtime, + now=self.now, ) if migrations_ran and migration_result is not None: @@ -289,8 +319,18 @@ class KantaImpl(PersistenceMixin, Generic[T]): ) if record is not None and log is not False: - logger = log if isinstance(log, logging.Logger) else bootstrap_logger - logger.info("Created %s", self.filename.resolve()) + logger = ( + log if isinstance(log, logging.Logger) else bootstrap_logger + ) + emit_event( + LogEvent( + kind="created", + logger=logger, + kanta=self._kanta, + filename=str(self.filename.resolve()), + ), + self.callback_registry.logemit_handlers, + ) logfmt = self.callback_registry.build_logfmt( InjectionContext( previous_state={}, @@ -303,14 +343,19 @@ class KantaImpl(PersistenceMixin, Generic[T]): resolved = logfmt(formatted_user, _USER_PATH) if resolved is not None: formatted_user = resolved - log_change( - self.bootstrap_action, - record.diff, - formatted_user, - previous={}, - logfmt=logfmt, - logger=logger, - level=logging.INFO, + emit_event( + LogEvent( + kind="change", + logger=logger, + kanta=self._kanta, + action=self.bootstrap_action, + user=formatted_user, + diff=record.diff, + previous={}, + current=current, + logfmt=logfmt, + ), + self.callback_registry.logemit_handlers, ) except Exception: self.opened = False diff --git a/kanta/logging.py b/kanta/logging.py index b4ed8f4..910ea26 100644 --- a/kanta/logging.py +++ b/kanta/logging.py @@ -1,20 +1,28 @@ """Database change logging with pretty-printed diffs. -Provides loggers for JSONL database changes, bootstrap events, and -migrations. Diff output is formatted in a human-readable path notation -style with color coding. +All change-related output is described by a :class:`LogEvent` and dispatched +through :func:`emit_event`, which runs any registered ``logemit`` callbacks +and falls back to :func:`default_emit` for the built-in formatting. Diff +output is formatted in a human-readable path notation style with color +coding; see :mod:`kanta.tty` for the color palette and line builder. """ import logging import re import sys -from collections.abc import Callable +from collections.abc import Callable, Iterable from typing import Any +import msgspec + +from kanta.tty import Line, displaywidth + transaction_logger = logging.getLogger("kanta.transaction") bootstrap_logger = logging.getLogger("kanta.bootstrap") migration_logger = logging.getLogger("kanta.migration") +_logger = logging.getLogger(__name__) + # Pattern to match control characters and bidirectional overrides _UNSAFE_CHARS = re.compile( r"[\x00-\x1f\x7f-\x9f" @@ -24,20 +32,151 @@ _UNSAFE_CHARS = re.compile( r"]" ) -# ANSI color codes -_RESET = "\033[0m" -_SEP = "\033[38;5;242m" # Dark grey for separators -_PATH_PREFIX = "\033[38;5;242m" # Dark grey for path prefix -_PATH_FINAL = "\033[38;5;250m" # Default for final element -_DELETE = "\033[1;31m" # Red for deletions -_ADD = "\033[0;32m" # Green for additions -_ACTION = "\033[1;34m" # Bold blue for action name -_USER = "\033[0;34m" # Blue for user display - # Metadata path used when formatting the transaction actor. _USER_PATH = "$user" +class LogEvent(msgspec.Struct, kw_only=True): + """All state describing one loggable event, passed to logemit callbacks. + + ``kind`` is ``"change"`` (transaction, bootstrap, or migration diff), + ``"created"`` (database file created), ``"migrated"`` (migration + summary), or ``"aborted"`` (transaction rolled back). ``logger`` and + ``level`` are Kanta's preferred destination; a callback may use them, + log elsewhere, or not log at all. + + The event is mutable: a callback may modify it before returning a truthy + value to pass it on, affecting later callbacks and the built-in fallback. + """ + + kind: str + logger: logging.Logger + level: int = logging.INFO + kanta: Any = None + action: str | None = None + user: str | None = None + extra: Any = None + error: BaseException | None = None + diff: dict = msgspec.field(default_factory=dict) + previous: dict | None = None + current: dict | None = None + logfmt: Callable[[Any, str], str | None] | None = None + show_diff: bool = True + filename: str | None = None + from_version: int | None = None + to_version: int | None = None + migrations: list[str] = msgspec.field(default_factory=list) + _header: str | None = None + _diff_lines: list[str] | None = None + + @property + def header(self) -> str: + """The default one-line header for this event, built on first access. + + Covers every event kind: ``"[ ][ by ]"`` for + changes, ``"[ ][ by ] transaction aborted: + "`` for aborts, and the plain ``Created``/``Migrated`` + summaries. + """ + if self._header is None: + self._header = self._build_header() + return self._header + + @header.setter + def header(self, value: str) -> None: + """Override the header, keeping the default diff routing. + + A logemit callback can restyle the header and return a truthy value: + :func:`default_emit` then logs this header instead of building one. + """ + self._header = value + + def _build_header(self) -> str: + if self.kind == "created": + return f"Created {self.filename}" + if self.kind == "migrated": + migrations = ", ".join(self.migrations) + return ( + f"Migrated {self.filename} " + f"v{self.from_version} -> v{self.to_version}: {migrations}" + ) + if self.kind == "change": + return format_action_header(self.action or "", self.user, self.extra) + line = Line().action(self.action or "") + if self.extra: + line(" ").target(self.extra) + if self.user: + line(" by ").user(self.user) + line(f" transaction aborted: {self.error}") + return str(line) + + @property + def diff_lines(self) -> list[str]: + """Pretty-printed diff lines, built on first access and cached.""" + if self._diff_lines is None: + self._diff_lines = format_diff(self.diff, self.previous, self.logfmt) + return self._diff_lines + + +def emit_event( + ev: LogEvent, + handlers: Iterable[Callable[[LogEvent], Any]] = (), +) -> None: + """Dispatch *ev* through registered logemit handlers. + + Each handler receives the event and may log it (or not) as it sees fit. + A falsy return value stops the chain: the event is considered handled. + A truthy return value passes the event — possibly modified — to the next + handler. When all handlers pass, :func:`default_emit` renders the event + with the built-in formatting. + + Logging must never break functionality: a crashing handler is reported + and the chain falls back to the built-in formatting, and a failure in + the built-in formatting itself is reported and swallowed. + """ + try: + for handler in handlers: + try: + proceed = handler(ev) + except Exception: + _logger.exception("logemit callback failed, using default formatting") + break + if not proceed: + return + default_emit(ev) + except Exception: + _logger.exception("failed to emit %s log event", ev.kind) + + +def default_emit(ev: LogEvent) -> None: + """Emit *ev* with Kanta's built-in formatting. + + Logs :attr:`LogEvent.header`; for change events the + :attr:`LogEvent.diff_lines` body follows on the ``.diff`` child + logger so it can be silenced or routed separately from the headers. + This is what runs when no logemit callback handles the event; custom + callbacks may call it to delegate events they do not care about. + """ + if ev.kind != "change": + ev.logger.log(ev.level, ev.header) + return + + diff_logger = logging.getLogger(f"{ev.logger.name}.diff") + lines = ev.diff_lines if ev.show_diff and diff_logger.isEnabledFor(ev.level) else [] + + if not lines: + ev.logger.log(ev.level, ev.header) + return + + if len(lines) == 1: + diff_logger.log(ev.level, f"{ev.header}{lines[0]}") + return + + ev.logger.log(ev.level, ev.header) + for line in lines: + diff_logger.log(ev.level, line) + + def _join_path(path: str, key: str) -> str: """Append *key* to a dot-notation *path*.""" if not path: @@ -116,17 +255,22 @@ def _format_path_components( def _format_path( - path: list[str], logfmt: Callable[[Any, str], str | None] | None + path: list[str], + logfmt: Callable[[Any, str], str | None] | None, + final_color: str = "path_final", ) -> str: - """Format a path as dot notation with prefix in dark grey, final in default.""" + """Format a path as dot notation with prefix in dark grey, final colored. + + *final_color* names a color in the :data:`kanta.tty.colors` palette. + """ components = _format_path_components(path, logfmt) if not components: return "" - if len(components) == 1: - return f"{_PATH_FINAL}{components[0]}{_RESET}" - prefix = ".".join(components[:-1]) - final = components[-1] - return f"{_PATH_PREFIX}{prefix}.{_RESET}{_PATH_FINAL}{final}{_RESET}" + line = Line() + if len(components) > 1: + line.path_prefix(".".join(components[:-1]) + ".") + getattr(line, final_color)(components[-1]) + return str(line) def _get_nested(data: dict | None, path: list[str]) -> Any: @@ -202,19 +346,18 @@ def _format_change_lines( logfmt: Callable[[Any, str], str | None] | None = None, ) -> list[str]: """Format a single change as one or more lines.""" - path_str = _format_path(path, logfmt=logfmt) - if change_type == "delete": components = _format_path_components(path, logfmt) - if len(components) == 1: - return [f" {_DELETE}{components[0]} ✗{_RESET}"] - prefix = ".".join(components[:-1]) - final = components[-1] - return [f" {_PATH_PREFIX}{prefix}.{_RESET}{_DELETE}{final} ✗{_RESET}"] + line = Line()(" ") + if len(components) > 1: + line.path_prefix(".".join(components[:-1]) + ".") + line.delete(components[-1], " ✗") + return [str(line)] if change_type == "add": + path_str = _format_path(path, logfmt, final_color="add") if isinstance(value, dict) and value: - lines = [f" {path_str} {_SEP}={_RESET}"] + lines = [str(Line()(" ", path_str, " ").sep("="))] formatted_items = [] base_path = ".".join(path) for k, v in value.items(): @@ -222,17 +365,22 @@ def _format_change_lines( key_display = _format_value(k, key_path, max_len=30, logfmt=logfmt) v_str = _format_value(v, key_path, max_len=30, logfmt=logfmt) formatted_items.append((key_display, v_str)) - max_key_len = max(len(k) for k, _ in formatted_items) - field_width = max(max_key_len, 12) - for k_display, v_str in formatted_items: - padding = " " * (field_width - len(k_display)) - lines.append(f" {k_display}{_SEP}:{_RESET}{padding} {v_str}") - return lines + field_width = max(displaywidth(k) for k, _ in formatted_items) + field_width = max(field_width, 12) + return lines + [ + str( + Line()(" ", k).sep(":")( + " " * (field_width - displaywidth(k)), " ", v + ) + ) + for k, v in formatted_items + ] value_str = _format_value(value, ".".join(path), logfmt=logfmt) - return [f" {path_str} {_SEP}={_RESET} {value_str}"] + return [str(Line()(" ", path_str, " ").sep("=")(" ", value_str))] value_str = _format_value(value, ".".join(path), logfmt=logfmt) - return [f" {path_str} {_SEP}={_RESET} {value_str}"] + path_str = _format_path(path, logfmt=logfmt) + return [str(Line()(" ", path_str, " ").sep("=")(" ", value_str))] def format_diff( @@ -262,13 +410,18 @@ def format_diff( return lines -def format_action_header(action: str, user: str | None = None) -> str: - """Format the action header line.""" - action_str = f"{_ACTION}{action}{_RESET}" - if user: - user_str = f"{_USER}{user}{_RESET}" - return f"{action_str} by {user_str}" - return action_str +def format_action_header( + action: str, + user: str | None = None, + extra: Any = None, +) -> str: + """Format the default action header line.""" + line = Line().action(action) + if extra is not None and (extra := f"{extra}"): + line(" ").target(extra) + if user is not None and (user := f"{user}"): + line(" by ").user(user) + return str(line) def log_change( @@ -276,35 +429,48 @@ def log_change( diff: dict, user: str | None = None, previous: dict | None = None, + extra: Any = None, logfmt: Callable[[Any, str], str | None] | None = None, *, logger: logging.Logger = transaction_logger, level: int = logging.INFO, + log_diff: bool = True, ) -> None: - """Log a database change with pretty-printed diff. + """Log a database change with the built-in formatting. + + Compatibility wrapper around :func:`emit_event` with no handlers; Kanta + itself builds a :class:`LogEvent` and dispatches it with the registered + logemit callbacks. Args: action: The action name (e.g., "login", "admin:delete_user"). diff: The JSON diff dict. user: Optional already-formatted user name to show in the header. previous: The previous state dict (for determining add vs update). + extra: Optional display-only value 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. logfmt: Optional formatter callable ``(value, path) -> str | None``. logger: Logger to write to. Defaults to the ``kanta.transaction`` logger. level: Log level to use. Defaults to ``logging.INFO``. + log_diff: Whether to build and emit the diff lines. ``False`` skips + diff formatting entirely and only the header is logged. """ - header = format_action_header(action, user) - diff_lines = format_diff(diff, previous, logfmt) - - if not diff_lines: - logger.log(level, header) - return - - if len(diff_lines) == 1: - logger.log(level, f"{header}{diff_lines[0]}") - else: - logger.log(level, header) - for line in diff_lines: - logger.log(level, line) + emit_event( + LogEvent( + kind="change", + logger=logger, + level=level, + action=action, + user=user, + extra=extra, + diff=diff, + previous=previous, + logfmt=logfmt, + show_diff=log_diff, + ) + ) def configure_logging( @@ -313,6 +479,7 @@ def configure_logging( bootstrap: bool = True, migration: bool = True, transaction: bool = True, + diff: bool = True, ) -> None: """Configure Kanta's default logging output. @@ -326,11 +493,17 @@ def configure_logging( bootstrap: Whether bootstrap logs are enabled. migration: Whether migration logs are enabled. transaction: Whether transaction logs are enabled. + diff: Whether transaction diff lines are enabled. When ``False``, + only transaction headers are printed and diff formatting is + skipped. Per transaction this is controlled by the ``logdiff`` + argument of :meth:`Kanta.transaction`. This helper is not called automatically; applications that want Kanta's default output can call it, but most applications will configure logging themselves. """ + logging.getLogger("kanta.transaction.diff").disabled = not diff + for name, enabled in ( ("kanta.bootstrap", bootstrap), ("kanta.migration", migration), diff --git a/kanta/persistence.py b/kanta/persistence.py index 5113256..81b0436 100644 --- a/kanta/persistence.py +++ b/kanta/persistence.py @@ -4,8 +4,10 @@ from __future__ import annotations import asyncio import copy +import inspect import logging from collections import deque +from collections.abc import Callable from datetime import UTC, datetime from pathlib import Path from typing import Any @@ -41,6 +43,7 @@ class PersistenceMixin: opened: bool readonly: bool mtime: datetime | None + clock: Callable[[], datetime] | None def __init__(self, **kwargs: Any) -> None: """Initialize persistence-owned state used by mixin methods.""" @@ -62,6 +65,31 @@ class PersistenceMixin: self.flush_interval = flush_interval self.version = 0 self.mtime: datetime | None = None + self.clock: Callable[[], datetime] | None = None + + def add_clock(self, callback) -> None: + """Register a clock callback ``() -> datetime`` replacing the UTC clock.""" + if not callable(callback): + raise TypeError("clock callback must be callable") + for param in inspect.signature(callback).parameters.values(): + if param.default is inspect.Parameter.empty and param.kind in ( + param.POSITIONAL_ONLY, + param.POSITIONAL_OR_KEYWORD, + param.KEYWORD_ONLY, + ): + raise TypeError("clock callback must not require arguments") + self.clock = callback + + def now(self) -> datetime: + """Current time from the registered clock (default: UTC now).""" + if self.clock is None: + return datetime.now(UTC) + ts = self.clock() + if not isinstance(ts, datetime): + raise TypeError( + f"clock callback must return a datetime, got {type(ts).__name__}" + ) + return ts def add_fatal_error(self, callback) -> None: """Register one fatal error callback in call order.""" @@ -100,7 +128,9 @@ class PersistenceMixin: def maybe_snapshot(self) -> None: """Evaluate and possibly write a snapshot from current state.""" - self.snapshot.maybe_write(self.file, self.version, self.statedict, m=self.mtime) + self.snapshot.maybe_write( + self.file, self.version, self.statedict, m=self.mtime, now=self.now + ) def queue_change( self, @@ -128,7 +158,14 @@ class PersistenceMixin: The queued :class:`ChangeRecord`, or ``None`` if the diff was empty and *force* is ``False``. """ - now = datetime.now(UTC) + diff = compute_diff(self.statedict, current) + if not diff: + if not force: + return None + diff = {} + + # The clock is only read when a record is actually queued. + now = self.now() if mtime is True: m = now @@ -139,12 +176,6 @@ class PersistenceMixin: else: raise TypeError("mtime must be True, False, or a datetime") - diff = compute_diff(self.statedict, current) - if not diff: - if not force: - return None - diff = {} - record = ChangeRecord( ts=now, a=action, diff --git a/kanta/snapshot.py b/kanta/snapshot.py index 8896f50..e97357b 100644 --- a/kanta/snapshot.py +++ b/kanta/snapshot.py @@ -3,6 +3,7 @@ from __future__ import annotations import logging +from collections.abc import Callable from datetime import UTC, datetime from kanta.structs import Snapshot @@ -38,23 +39,29 @@ class SnapshotState: self.changes += count def maybe_write( - self, file, version: int, state: dict, m: datetime | None = None + self, + file, + version: int, + state: dict, + m: datetime | None = None, + now: Callable[[], datetime] | None = None, ) -> None: """Write snapshot when thresholds/time policy allows it.""" force = self._force_pending - now = datetime.now(UTC) + if not force and self.changes < self._min_diffs: + return + # The clock is only read when a snapshot may actually be written. + ts = now() if now is not None else datetime.now(UTC) if not force: - if self.changes < self._min_diffs: + if ts.weekday() != 6: # 6 = Sunday return - if now.weekday() != 6: # 6 = Sunday - return - sunday_midnight = now.replace(hour=0, minute=0, second=0, microsecond=0) + sunday_midnight = ts.replace(hour=0, minute=0, second=0, microsecond=0) if self.ts is not None and self.ts >= sunday_midnight: return if not file.is_open: return try: - self._write(file, version, state, now, m=m) + 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) diff --git a/kanta/transaction.py b/kanta/transaction.py index 80b4803..bea48a5 100644 --- a/kanta/transaction.py +++ b/kanta/transaction.py @@ -5,24 +5,46 @@ from __future__ import annotations import logging from contextlib import contextmanager from datetime import datetime +from typing import Any from kanta.diff import compute_diff from kanta.exceptions import DataIntegrityError from kanta.callbacks import InjectionContext -from kanta.logging import _USER_PATH, log_change, transaction_logger +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__) +def _build_logfmt(impl, previous: dict, current: dict): + """Build the logfmt chain for a state transition.""" + return impl.callback_registry.build_logfmt( + InjectionContext( + previous_state=previous, + current_state=current, + kanta=impl._kanta, + ) + ) + + +def _resolve_user(logfmt, user: str | None) -> str | None: + """Resolve *user* for display via the logfmt chain (raw as fallback).""" + if user is None: + return None + resolved = logfmt(user, _USER_PATH) + return resolved if resolved is not None else user + + @contextmanager def transaction( impl, action: str, *, user: str | None = None, + extra: Any = None, mtime: bool | datetime = True, log: bool | logging.Logger = True, + logdiff: bool = True, ): """Wrap writes in a transaction and yield the live db object.""" if impl.readonly: @@ -69,30 +91,45 @@ def transaction( previous = impl.statedict record = impl.queue_change(action, new_dict, user=user, mtime=mtime) if record is not None: - logfmt = impl.callback_registry.build_logfmt( - InjectionContext( - previous_state=previous, - current_state=new_dict, - kanta=impl._kanta, - ) - ) - formatted_user = user - if user is not None and logfmt is not None: - resolved = logfmt(user, _USER_PATH) - if resolved is not None: - formatted_user = resolved if log is not False: - logger = log if isinstance(log, logging.Logger) else transaction_logger - log_change( - action, - record.diff, - formatted_user, - previous, - logfmt, - logger=logger, + logfmt = _build_logfmt(impl, previous, new_dict) + logger = ( + log if isinstance(log, logging.Logger) else transaction_logger ) - except Exception: - _logger.warning("Transaction '%s' failed, rolling back changes", action) + emit_event( + LogEvent( + kind="change", + logger=logger, + kanta=impl._kanta, + action=action, + user=_resolve_user(logfmt, user), + extra=extra, + diff=record.diff, + previous=previous, + current=new_dict, + logfmt=logfmt, + show_diff=logdiff, + ), + impl.callback_registry.logemit_handlers, + ) + except Exception as exc: + resolved_user = None + if user is not None: + logfmt = _build_logfmt(impl, impl.statedict, impl.statedict) + resolved_user = _resolve_user(logfmt, user) + emit_event( + LogEvent( + kind="aborted", + logger=transaction_logger, + level=logging.WARNING, + kanta=impl._kanta, + action=action, + user=resolved_user, + extra=extra, + error=exc, + ), + impl.callback_registry.logemit_handlers, + ) if impl.transaction_snapshot is not None: impl.data = restore_data_in_place( impl.data, diff --git a/kanta/tty.py b/kanta/tty.py new file mode 100644 index 0000000..b145fa9 --- /dev/null +++ b/kanta/tty.py @@ -0,0 +1,181 @@ +"""Terminal string building: ANSI colors, display widths, and a line builder. + +Colors are stored as bare SGR parameter strings (e.g. ``"1;34"``) without +the ``\\x1b[`` prefix and ``m`` suffix. The :class:`Line` builder understands +how SGR parameters stack: ``0`` clears everything, other parameters apply +sequentially and the last one of each class wins. This lets it emit minimal +escape sequences, folding a needed reset into the same sequence as the next +color instead of emitting a separate one. +""" + +from __future__ import annotations + +import re +import unicodedata +from typing import Any + +ESC = "\x1b[" + +# Matches a full ANSI escape sequence (color codes, cursor movement, ...). +ANSI_RE = re.compile(r"\x1b\[[0-9;:]*[A-Za-z]") + + +def strip_ansi(text: str) -> str: + """Remove ANSI escape sequences from *text*.""" + return ANSI_RE.sub("", text) + + +def displaywidth(text: str) -> int: + """Return the terminal column width of *text*, ignoring ANSI sequences. + + Wide characters (CJK, most emoji) count as two columns; combining and + zero-width characters count as zero. + """ + return sum( + 2 + if unicodedata.east_asian_width(c) in "WF" + else 0 + if unicodedata.category(c) in ("Mn", "Me", "Cf") + else 1 + for c in strip_ansi(text) + ) + + +def pad(text: str, width: int, align: str = "left") -> str: + """Pad *text* to *width* columns by display width. + + *align* is ``"left"`` (padding after), ``"right"`` (padding before), or + ``"center"``. Text already at or above *width* is returned unchanged. + """ + missing = width - displaywidth(text) + if missing <= 0: + return text + if align == "right": + return " " * missing + text + if align == "center": + left = missing // 2 + return " " * left + text + " " * (missing - left) + return text + " " * missing + + +class Colors: + """Kanta's log color palette: bare SGR parameter strings. + + Attributes are looked up when a line is rendered, so assignments such as + ``colors.action = "36"`` or additions like ``colors.session = "38;5;226"`` + take effect immediately, no matter how the object was imported. Added + colors become available on :class:`Line` under the same name. + """ + + action = "1;34" # Bold blue for the action name + user = "34" # Blue for the user display + target = "38;5;250" # White for the extra/target display + sep = "38;5;242" # Dark grey for separators + path_prefix = "38;5;242" # Dark grey for the leading part of a dotted path + path_final = "38;5;250" # White for the final path element + add = "32" # Green for additions + delete = "1;31" # Bold red for deletions + + +colors = Colors() + +# SGR attribute classes that carry no class siblings (each clears/sets itself). +_ATTR_CLASSES = frozenset({"1", "2", "3", "4", "7", "9"}) + + +def _parse_sgr(spec: str) -> dict[str, str]: + """Parse a bare SGR parameter string into a ``{class: group}`` state. + + Applies the stacking rules: ``0`` clears everything, other parameters + apply sequentially and the last one of each class wins. + """ + state: dict[str, str] = {} + tokens = spec.split(";") + i = 0 + while i < len(tokens): + token = tokens[i] + if token == "0": + state.clear() + elif token in ("38", "48"): + cls = "fg" if token == "38" else "bg" + if i + 1 < len(tokens) and tokens[i + 1] == "5": + state[cls] = ";".join(tokens[i : i + 3]) + i += 3 + continue + if i + 1 < len(tokens) and tokens[i + 1] == "2": + state[cls] = ";".join(tokens[i : i + 4]) + i += 4 + continue + state[cls] = token + elif token.isdigit() and (30 <= int(token) <= 37 or 90 <= int(token) <= 97): + state["fg"] = token + elif token.isdigit() and (40 <= int(token) <= 47 or 100 <= int(token) <= 107): + state["bg"] = token + elif token in _ATTR_CLASSES: + state[token] = token + else: + state[f"other:{token}"] = token + i += 1 + return state + + +def _sgr_transition(current: dict[str, str], new: dict[str, str]) -> str: + """Return the minimal escape sequence moving from *current* to *new*.""" + if current == new: + return "" + if not new: + return f"{ESC}0m" if current else "" + if not current: + return f"{ESC}{';'.join(new.values())}m" + if current.keys() - new.keys(): + # Some attribute must be cleared; fold the reset into one sequence. + return f"{ESC}0;{';'.join(new.values())}m" + changed = [group for cls, group in new.items() if current.get(cls) != group] + return f"{ESC}{';'.join(changed)}m" if changed else "" + + +class Line: + """Build a terminal string part by part with colors, width and alignment. + + Calling the builder appends content (arguments are converted to ``str``). + Attribute access with a color name arms that palette color for the next + call; the color is reset automatically when that call ends, so a color + always applies to exactly one call:: + + str(Line().user("Alice")(" by ")) # "Alice" blue, " by " plain + + ``width`` and ``align`` keyword arguments pad the content of a call by + display width. ``str(line)`` finishes the line, restoring default + colors if any are active. + """ + + def __init__(self, palette: Colors | None = None) -> None: + self._palette = palette if palette is not None else colors + self._parts: list[str] = [] + self._active: dict[str, str] = {} + self._pending: dict[str, str] = {} + + def __getattr__(self, name: str) -> Line: + if name.startswith("_"): + raise AttributeError(name) + spec = getattr(self._palette, name, None) + if spec is None: + raise AttributeError(f"unknown color: {name!r}") + self._pending = _parse_sgr(spec) + return self + + def __call__(self, *args: Any, width: int = 0, align: str = "left") -> Line: + text = "".join(str(arg) for arg in args) + if width: + text = pad(text, width, align) + if self._pending != self._active: + self._parts.append(_sgr_transition(self._active, self._pending)) + self._active = self._pending + self._parts.append(text) + self._pending = {} + return self + + def __str__(self) -> str: + if self._active: + return "".join(self._parts) + f"{ESC}0m" + return "".join(self._parts) diff --git a/tests/test_clock.py b/tests/test_clock.py new file mode 100644 index 0000000..4845996 --- /dev/null +++ b/tests/test_clock.py @@ -0,0 +1,135 @@ +from datetime import UTC, datetime, timedelta + +import pytest + +from .support import ( + Data, + make_kanta, + make_migrations_module, + read_changes, + read_last_snapshot, +) + +T0 = datetime(2026, 1, 1, 12, 0, tzinfo=UTC) + + +def test_clock_rejects_non_callable(tmp_path, format_config): + kanta = make_kanta(tmp_path / "test.db", Data, format_config) + + with pytest.raises(TypeError, match="must be callable"): + kanta.clock(42) + + +def test_clock_rejects_required_argument(tmp_path, format_config): + kanta = make_kanta(tmp_path / "test.db", Data, format_config) + + with pytest.raises(TypeError, match="must not require arguments"): + + @kanta.clock + def fake_now(tz) -> datetime: + return T0 + + +@pytest.mark.asyncio +async def test_clock_rejects_non_datetime_result(tmp_path, format_config): + kanta = make_kanta(tmp_path / "test.db", Data, format_config) + + @kanta.clock + def fake_now() -> datetime: + return "noon" + + with pytest.raises(TypeError, match="must return a datetime"): + await kanta.open(log=False) + + +@pytest.mark.asyncio +async def test_clock_controls_record_timestamps(tmp_path, format_config): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + current = T0 + + @kanta.clock + def fake_now() -> datetime: + return current + + await kanta.open(log=False) + current = T0 + timedelta(hours=1) + with kanta.transaction(action="update") as data: + data.counter = 1 + current = T0 + timedelta(hours=2) + with kanta.transaction(action="repair", mtime=False) as data: + data.counter = 2 + await kanta.close() + + bootstrap, update, repair = read_changes(path, format_config) + assert bootstrap.ts == T0 + assert bootstrap.m == T0 + assert update.ts == T0 + timedelta(hours=1) + assert update.m == T0 + timedelta(hours=1) + # System operation: stamped by the clock, but m is not updated. + assert repair.ts == T0 + timedelta(hours=2) + assert repair.m is None + assert kanta.mtime == T0 + timedelta(hours=1) + + +@pytest.mark.asyncio +async def test_clock_not_read_without_changes(tmp_path, format_config): + kanta = make_kanta(tmp_path / "test.db", Data, format_config) + reads = 0 + + @kanta.clock + def fake_now() -> datetime: + nonlocal reads + reads += 1 + return T0 + + await kanta.open(log=False) # bootstrap record: one read + reads = 0 + + with kanta.transaction(action="noop"): + pass # no changes, no record, no clock read + await kanta.close() # no snapshot written, no clock read + + assert reads == 0 + + +@pytest.mark.asyncio +async def test_clock_controls_migration_and_snapshot_timestamps( + tmp_path, format_config +): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + + @kanta.clock + def fake_now() -> datetime: + return T0 + + await kanta.open(log=False) + await kanta.close() + + def migrate_v1(d): + """Bump counter""" + d["counter"] = 1 + + migrations = make_migrations_module("clock_migrations", "migrate_v1", migrate_v1) + t1 = T0 + timedelta(days=1) + kanta2 = make_kanta(path, Data, format_config, migrations=migrations) + + @kanta2.clock + def fake_now2() -> datetime: + return t1 + + await kanta2.open(log=False) + await kanta2.close() + + migrate_records = [ + r for r in read_changes(path, format_config) if r.a.startswith("migrate:") + ] + assert migrate_records + assert all(r.ts == t1 for r in migrate_records) + + snapshot = read_last_snapshot(path, format_config) + assert snapshot is not None + assert snapshot.ts == t1 + # mtime is carried forward from the last real modification. + assert snapshot.m == T0 diff --git a/tests/test_format_diff.py b/tests/test_format_diff.py index 9bd9e05..6127f13 100644 --- a/tests/test_format_diff.py +++ b/tests/test_format_diff.py @@ -1,4 +1,8 @@ from kanta.logging import format_diff +from kanta.tty import ESC, colors + +_ADD = f"{ESC}{colors.add}m" +_DELETE = f"{ESC}{colors.delete}m" def test_add(): @@ -6,6 +10,28 @@ def test_add(): assert any("name" in line for line in lines) +def test_add_path_is_green(): + lines = format_diff({"name": "Alice"}, previous={}) + assert any(_ADD in line for line in lines) + + +def test_nested_add_path_final_element_is_green(): + lines = format_diff({"users": {"alice": 1}}, previous={"users": {}}) + assert any(_ADD in line and "alice" in line for line in lines) + + +def test_update_path_not_colored_as_add(): + lines = format_diff({"name": "Bob"}, previous={"name": "Alice"}) + assert lines + assert all(_ADD not in line for line in lines) + + +def test_delete_path_not_colored_as_add(): + lines = format_diff({"$delete": ["old_key"]}, previous={"old_key": 1}) + assert any(_DELETE in line for line in lines) + assert all(_ADD not in line for line in lines) + + def test_update(): lines = format_diff({"name": "Bob"}, previous={"name": "Alice"}) assert any("Bob" in line for line in lines) diff --git a/tests/test_kanta_integration.py b/tests/test_kanta_integration.py index 94f97ba..46b2ad1 100644 --- a/tests/test_kanta_integration.py +++ b/tests/test_kanta_integration.py @@ -738,6 +738,26 @@ async def test_transaction_log_false_suppresses_log(tmp_path, format_config, cap assert not info_messages +@pytest.mark.asyncio +async def test_transaction_logdiff_false_logs_header_only( + tmp_path, format_config, caplog +): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + await kanta.open() + + with caplog.at_level(logging.INFO, logger="kanta.transaction"): + with kanta.transaction(action="inc", logdiff=False) as data: + data.counter = 1 + + await kanta.close() + + messages = [r.message for r in caplog.records if r.levelno == logging.INFO] + assert len(messages) == 1 + assert "inc" in messages[0] + assert "counter" not in messages[0] + + @pytest.mark.asyncio async def test_transaction_log_custom_logger(tmp_path, format_config, caplog): path = tmp_path / "test.db" diff --git a/tests/test_logemit.py b/tests/test_logemit.py new file mode 100644 index 0000000..7613627 --- /dev/null +++ b/tests/test_logemit.py @@ -0,0 +1,362 @@ +import logging +import sys + +import pytest + +from kanta.logging import ( + LogEvent, + bootstrap_logger, + configure_logging, + emit_event, + log_change, + migration_logger, + transaction_logger, +) +from kanta.migrations import MigrationResult +from tests.support import ( + Data, + fixed_change, + make_kanta, + seed_single_change, +) + + +@pytest.fixture(autouse=True) +def _reset_kanta_loggers(): + yield + for name in ( + "kanta", + "kanta.transaction", + "kanta.transaction.diff", + "kanta.bootstrap", + "kanta.migration", + ): + logger = logging.getLogger(name) + logger.setLevel(logging.NOTSET) + logger.propagate = True + logger.disabled = False + logger.handlers.clear() + + +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() + calls = [] + + def first(ev): + calls.append("first") + return None + + def second(ev): + calls.append("second") + + emit_event(_change_event(), [first, second]) + assert calls == ["first"] + assert capsys.readouterr().err == "" + + +def test_emit_event_truthy_return_falls_back_to_default(capsys): + logging.getLogger("kanta").handlers.clear() + configure_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() + calls = [] + + def first(ev): + calls.append("first") + ev.extra = "tgt" + return True + + def second(ev): + calls.append(("second", ev.extra)) + return True + + emit_event(_change_event(), [first, second]) + assert calls == ["first", ("second", "tgt")] + assert "tgt" in capsys.readouterr().err + + +def test_emit_event_handler_error_falls_back_to_default(capsys): + logging.getLogger("kanta").handlers.clear() + configure_logging() + + def boom(ev): + raise RuntimeError("broken") + + emit_event(_change_event(), [boom]) + assert "update" in capsys.readouterr().err + + +def test_diff_lines_built_lazily(monkeypatch): + def _boom(*args, **kwargs): + raise AssertionError("format_diff should not be called") + + monkeypatch.setattr("kanta.logging.format_diff", _boom) + ev = _change_event(diff={"counter": 1}) + emit_event(ev, [lambda ev: None]) # handled without touching the diff + monkeypatch.undo() + assert len(ev.diff_lines) == 1 + assert "counter" in ev.diff_lines[0] + + +def test_default_emit_created_and_migrated(capsys): + logging.getLogger("kanta").handlers.clear() + configure_logging() + emit_event(LogEvent(kind="created", logger=bootstrap_logger, filename="x.kantadb")) + emit_event( + LogEvent( + kind="migrated", + logger=migration_logger, + filename="x.kantadb", + from_version=0, + to_version=1, + migrations=["migrate_v1 (rename)"], + ) + ) + err = capsys.readouterr().err + assert "Created x.kantadb" in err + assert "Migrated x.kantadb v0 -> v1: migrate_v1 (rename)" in err + + +@pytest.mark.asyncio +async def test_logemit_receives_transaction_events(tmp_path, format_config): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + events = [] + kanta.logemit(lambda ev: events.append(ev) or True) + await kanta.open() + + with kanta.transaction(action="inc", user="u1", extra="x") as data: + data.counter = 1 + + await kanta.close() + + change = events[-1] + assert change.kind == "change" + assert change.action == "inc" + assert change.user == "u1" + assert change.extra == "x" + assert change.diff == {"counter": 1} + assert change.logger.name == "kanta.transaction" + + +def test_logemit_rejects_classes_and_async(tmp_path, format_config): + kanta = make_kanta(tmp_path / "test.db", Data, format_config) + + class NotAFunction: + pass + + with pytest.raises(TypeError): + kanta.logemit(NotAFunction) + + async def ahandler(ev): + return None + + with pytest.raises(TypeError): + kanta.logemit(ahandler) + + +def _raise(*args, **kwargs): + raise RuntimeError("formatting broken") + + +def test_log_change_never_raises(monkeypatch): + monkeypatch.setattr("kanta.logging.format_action_header", _raise) + log_change("update", {"counter": 1}, previous={}) # must not raise + + +@pytest.mark.asyncio +async def test_logging_failure_does_not_break_transaction( + tmp_path, format_config, monkeypatch +): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + kanta.logemit(_raise) + monkeypatch.setattr("kanta.logging.format_action_header", _raise) + await kanta.open() + + with kanta.transaction(action="inc") as data: + data.counter = 1 + + await kanta.close() + + kanta2 = make_kanta(path, Data, format_config) + kanta2.logemit(_raise) + monkeypatch.setattr("kanta.logging.format_action_header", _raise) + await kanta2.open() + assert kanta2.data.counter == 1 + await kanta2.close() + + +@pytest.mark.asyncio +async def test_logfmt_failure_falls_back_to_default(tmp_path, format_config, caplog): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + + @kanta.logfmt + def bad(value: str, path: str) -> str | None: + raise RuntimeError("broken") + + await kanta.open() + with caplog.at_level(logging.INFO, logger="kanta.transaction"): + with kanta.transaction(action="inc", user="alice") as data: + data.counter = 1 + await kanta.close() + + assert kanta.data.counter == 1 + assert "alice" in caplog.text # raw rendering used despite the failure + assert "counter" in caplog.text + + +@pytest.mark.asyncio +async def test_logmigr_failure_does_not_break_open(tmp_path, format_config): + path = tmp_path / "test.db" + seed_single_change(path, fixed_change("init", {"counter": 0}), format_config) + + mod = type(sys)("test_migrations_broken_logmigr") + + def migrate_v1(d, kanta): + """Bump counter.""" + d["counter"] = 2 + + mod.__dict__["migrate_v1"] = migrate_v1 + + kanta = make_kanta(path, Data, format_config, migrations=mod) + + @kanta.logmigr + def bad(summary: MigrationResult) -> None: + raise RuntimeError("broken") + + await kanta.open() + assert kanta.data.counter == 2 + await kanta.close() + + +@pytest.mark.asyncio +async def test_aborted_transaction_emits_event(tmp_path, format_config, caplog): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + events = [] + kanta.logemit(lambda ev: events.append(ev) or True) + await kanta.open() + + with caplog.at_level(logging.WARNING, logger="kanta.transaction"): + with pytest.raises(ValueError): + with kanta.transaction(action="reset") as data: + data.counter = 99 + raise ValueError("simulated failure") + + await kanta.close() + + aborted = events[-1] + assert aborted.kind == "aborted" + assert aborted.action == "reset" + assert aborted.level == logging.WARNING + assert isinstance(aborted.error, ValueError) + messages = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING] + assert any("\x1b[1;34mreset" in m for m in messages) # action color, no quotes + assert any(" transaction aborted: simulated failure" in m for m in messages) + assert kanta.data.counter == 0 # rolled back + + +@pytest.mark.asyncio +async def test_aborted_transaction_includes_resolved_user( + tmp_path, format_config, caplog +): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + + @kanta.logfmt + def resolve(value: str, path: str) -> str | None: + return "Alice" if value == "u1" else None + + await kanta.open() + with caplog.at_level(logging.WARNING, logger="kanta.transaction"): + with pytest.raises(ValueError): + with kanta.transaction(action="reset", user="u1", extra="exp") as data: + data.counter = 99 + raise ValueError("boom") + await kanta.close() + + messages = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING] + assert any("exp" in m for m in messages) + assert any(" by " in m and "Alice" in m for m in messages) + assert any(" transaction aborted: boom" in m for m in messages) + + +def test_event_header_covers_all_kinds(): + created = LogEvent(kind="created", logger=transaction_logger, filename="x.db") + assert created.header == "Created x.db" + + migrated = LogEvent( + kind="migrated", + logger=transaction_logger, + filename="x.db", + from_version=0, + to_version=1, + migrations=["migrate_v1 (rename)"], + ) + assert migrated.header == "Migrated x.db v0 -> v1: migrate_v1 (rename)" + + aborted = LogEvent( + kind="aborted", + logger=transaction_logger, + action="reset", + user="alice", + error=ValueError("boom"), + ) + assert "transaction aborted: boom" in aborted.header + assert "alice" in aborted.header + + +@pytest.mark.asyncio +async def test_event_carries_kanta_instance(tmp_path, format_config): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + events = [] + kanta.logemit(lambda ev: events.append(ev) or True) + await kanta.open() + with kanta.transaction(action="inc") as data: + data.counter = 1 + await kanta.close() + + assert events + assert all(ev.kanta is kanta for ev in events) + + +def test_header_is_settable_and_used_by_default_emit(capsys): + logging.getLogger("kanta").handlers.clear() + configure_logging() + + def restyle(ev): + ev.header = f"CUSTOM {ev.action}" + return True + + emit_event(_change_event(diff={"counter": 1}, previous={}), [restyle]) + err = capsys.readouterr().err + assert "CUSTOM update" in err + assert "counter" in err # default diff routing still applies + + +@pytest.mark.asyncio +async def test_ctx_reachable_from_event(tmp_path, format_config): + path = tmp_path / "test.db" + kanta = make_kanta(path, Data, format_config) + kanta.ctx.connection_id = 7 + seen = [] + kanta.logemit(lambda ev: seen.append(ev.kanta.ctx.connection_id) or True) + await kanta.open() + with kanta.transaction(action="inc") as data: + data.counter = 1 + await kanta.close() + + assert seen and all(connection_id == 7 for connection_id in seen) diff --git a/tests/test_logging.py b/tests/test_logging.py index 739c3d5..52960c5 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -2,16 +2,39 @@ import logging import pytest -from kanta.logging import configure_logging, log_change, transaction_logger +from kanta.logging import ( + configure_logging, + format_action_header, + log_change, +) +from kanta.tty import ESC + + +def test_format_action_header(): + header = format_action_header("update", "alice", "tgt") + assert header == ( + f"{ESC}1;34mupdate{ESC}0m {ESC}38;5;250mtgt{ESC}0m by {ESC}34malice{ESC}0m" + ) + + +def test_format_action_header_action_only(): + assert format_action_header("update") == f"{ESC}1;34mupdate{ESC}0m" @pytest.fixture(autouse=True) def _reset_kanta_loggers(): yield - for name in ("kanta", "kanta.transaction", "kanta.bootstrap", "kanta.migration"): + for name in ( + "kanta", + "kanta.transaction", + "kanta.transaction.diff", + "kanta.bootstrap", + "kanta.migration", + ): logger = logging.getLogger(name) logger.setLevel(logging.NOTSET) logger.propagate = True + logger.disabled = False logger.handlers.clear() @@ -46,3 +69,48 @@ def test_log_change_no_diff(capsys): log_change("test", {}) captured = capsys.readouterr() assert "test" in captured.err + + +def test_log_change_appends_extra_string(capsys): + kanta_logger = logging.getLogger("kanta") + kanta_logger.handlers.clear() + configure_logging() + log_change("export", {}, extra="mydb.db") + captured = capsys.readouterr() + assert "export" in captured.err + assert f"{ESC}38;5;250mmydb.db{ESC}0m" in captured.err + + +def test_log_change_log_diff_false(capsys, monkeypatch): + kanta_logger = logging.getLogger("kanta") + kanta_logger.handlers.clear() + configure_logging() + + def _boom(*args, **kwargs): + raise AssertionError("format_diff should not be called") + + monkeypatch.setattr("kanta.logging.format_diff", _boom) + log_change("update", {"counter": 5}, previous={}, log_diff=False) + captured = capsys.readouterr() + assert "update" in captured.err + assert "counter" not in captured.err + + +def test_configure_logging_diff_false(capsys): + kanta_logger = logging.getLogger("kanta") + kanta_logger.handlers.clear() + configure_logging(diff=False) + log_change("update", {"counter": 5}, previous={}) + captured = capsys.readouterr() + assert "update" in captured.err + assert "counter" not in captured.err + + +def test_configure_logging_diff_true_reenables(capsys): + kanta_logger = logging.getLogger("kanta") + kanta_logger.handlers.clear() + configure_logging(diff=False) + configure_logging(diff=True) + log_change("update", {"counter": 5}, previous={}) + captured = capsys.readouterr() + assert "counter" in captured.err diff --git a/tests/test_tty.py b/tests/test_tty.py new file mode 100644 index 0000000..d070f71 --- /dev/null +++ b/tests/test_tty.py @@ -0,0 +1,74 @@ +import pytest + +from kanta.tty import ESC, Colors, Line, colors, displaywidth, pad, strip_ansi + + +def test_strip_ansi(): + assert strip_ansi(f"{ESC}1;34mhello{ESC}0m") == "hello" + + +def test_displaywidth_plain_and_ansi(): + assert displaywidth("hello") == 5 + assert displaywidth(f"{ESC}38;5;226mhi{ESC}0m") == 2 + + +def test_displaywidth_wide_and_combining_chars(): + assert displaywidth("你好") == 4 + assert displaywidth("🚀") == 2 + assert displaywidth("é") == 1 + + +def test_pad(): + assert pad("ab", 4) == "ab " + assert pad("ab", 4, align="right") == " ab" + assert pad("ab", 5, align="center") == " ab " + assert pad("abcdef", 4) == "abcdef" + assert pad("你好", 6) == "你好 " + + +def test_line_plain_and_str_conversion(): + assert str(Line()("n=", 42)) == "n=42" + + +def test_line_color_auto_resets_on_next_call(): + assert str(Line().user("Alice")(" by ")) == f"{ESC}34mAlice{ESC}0m by " + + +def test_line_str_restores_active_color(): + assert str(Line().user("Alice")) == f"{ESC}34mAlice{ESC}0m" + + +def test_line_same_color_not_reemitted(): + assert str(Line().user("a").user("b")) == f"{ESC}34mab{ESC}0m" + + +def test_line_transition_folds_reset_into_one_sequence(): + # bold blue -> plain blue: the bold clear rides in the same sequence + assert str(Line().action("a").user("b")) == f"{ESC}1;34ma{ESC}0;34mb{ESC}0m" + + +def test_line_unknown_color_raises(): + with pytest.raises(AttributeError, match="unknown color"): + Line().nosuchcolor("x") + + +def test_line_palette_addition(monkeypatch): + monkeypatch.setattr(colors, "session", "38;5;226", raising=False) + assert str(Line().session("3")) == f"{ESC}38;5;226m3{ESC}0m" + + +def test_line_palette_override_takes_effect(monkeypatch): + monkeypatch.setattr(colors, "user", "36") + assert str(Line().user("x")) == f"{ESC}36mx{ESC}0m" + + +def test_line_custom_palette(): + palette = Colors() + palette.brand = "35" + assert str(Line(palette).brand("x")) == f"{ESC}35mx{ESC}0m" + + +def test_line_width_and_align(): + assert str(Line()("ab", width=4)) == "ab " + assert str(Line()("ab", width=4, align="right")) == " ab" + assert str(Line().user("ab", width=4)) == f"{ESC}34mab {ESC}0m"