Implement richer, fully customizable logging; customizable timestamps #1
+37
-57
@@ -1,15 +1,5 @@
|
||||
"""Kanta feature demo.
|
||||
|
||||
Run from the project root: python demo/main.py
|
||||
|
||||
Demonstrates bootstrap, colored transaction diffs, logfmt value formatting,
|
||||
logging toggles, rollback, migrations, and a custom clock.
|
||||
The database is recreated with fixed timestamps on every run; everything else
|
||||
lives in this file.
|
||||
"""
|
||||
|
||||
#!/usr/bin/env -S uv run
|
||||
import asyncio
|
||||
import logging
|
||||
import sys
|
||||
from datetime import UTC, datetime, timedelta
|
||||
from pathlib import Path
|
||||
@@ -38,34 +28,24 @@ kanta_v0 = Kanta(filename, Data())
|
||||
@kanta_v0.bootstrap
|
||||
def bootstrap(data: Data) -> None:
|
||||
"""Create the initial admin user."""
|
||||
data.users["u1"] = {"name": "Alice", "role": "admin"}
|
||||
data.users["userid001"] = {"name": "Alice", "role": "admin"}
|
||||
|
||||
|
||||
# Redefinition to simulate new version with counter renamed to total
|
||||
# Redefinition to simulate new version
|
||||
class Data(msgspec.Struct):
|
||||
users: dict[str, dict] = {}
|
||||
total: int = 0
|
||||
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.pop("counter")
|
||||
d["total"] = d["counter"]
|
||||
|
||||
|
||||
kanta_v1 = Kanta(filename, Data(), migrations=sys.modules[__name__])
|
||||
|
||||
|
||||
_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
|
||||
|
||||
|
||||
@kanta_v0.logfmt
|
||||
@kanta_v1.logfmt
|
||||
def resolve_user(
|
||||
@@ -82,61 +62,61 @@ def resolve_user(
|
||||
return None
|
||||
|
||||
|
||||
def section(title: str) -> None:
|
||||
print(f"\n# {title}", flush=True)
|
||||
|
||||
|
||||
async def main() -> None:
|
||||
filename.unlink(missing_ok=True)
|
||||
|
||||
section("Database creation with v0 schema and basic access")
|
||||
print("# Database creation with v0 schema and basic ops, pretty logs", flush=True)
|
||||
# Open and close automatically; you can also `await kanta.open()` instead
|
||||
async with kanta_v0 as kanta:
|
||||
with kanta.transaction(action="create", user="u2") as data:
|
||||
data.users["u2"] = {"name": "Bob", "role": "user"}
|
||||
with kanta.transaction(action="create", user="userid001") as data:
|
||||
data.users["userid002"] = {"name": "Bob", "role": "user"}
|
||||
|
||||
with kanta.transaction(action="update", user="u1") as data:
|
||||
data.users["u2"]["role"] = "editor"
|
||||
with kanta.transaction(action="update", user="userid001") as data:
|
||||
data.users["userid002"]["role"] = "editor"
|
||||
data.counter = 1
|
||||
|
||||
with kanta.transaction(action="delete", user="u1") as data:
|
||||
del data.users["u2"]
|
||||
with kanta.transaction(action="delete", user="userid002") as data:
|
||||
del data.users["userid001"]
|
||||
|
||||
# Display-only extra string, appended after the action.
|
||||
with kanta.transaction(action="export", user="u1", extra=filename.name) as data:
|
||||
with kanta.transaction(
|
||||
action="export", user="userid002", extra="extra info"
|
||||
) as data:
|
||||
data.counter = 2
|
||||
|
||||
# Compact logging, diff only: a system fix stamped by the clock, but the
|
||||
# modification time (m) is not updated.
|
||||
with kanta.transaction(
|
||||
action="repair", mtime=False, log={"header": False, "diff": True}
|
||||
) as data:
|
||||
data.users["u3"] = {"name": "Carol", "role": "user"}
|
||||
|
||||
# A failing transaction rolls back and logs a warning.
|
||||
try:
|
||||
with kanta.transaction(action="reset", user="u1") as data:
|
||||
with kanta.transaction(action="reset") as data:
|
||||
data.counter = 99
|
||||
raise ValueError("simulated failure")
|
||||
except ValueError:
|
||||
pass
|
||||
print(f"# Reading does not need transaction: {data.counter=}", flush=True)
|
||||
|
||||
# Compact logging, header only.
|
||||
with kanta.transaction(
|
||||
action="import", user="u1", log={"header": True, "diff": False}
|
||||
) as data:
|
||||
with kanta.transaction(action="import", logdiff=False) as data:
|
||||
data.counter = 3
|
||||
|
||||
section("A later version of our application with new data model and migrations")
|
||||
print(
|
||||
"\n# A later version of our application with new data model and migrations",
|
||||
flush=True,
|
||||
)
|
||||
async with kanta_v1 as kanta:
|
||||
with kanta.transaction(action="update", user="u1", extra=filename.name) as data:
|
||||
with kanta.transaction(
|
||||
action="update", user="userid002", extra=filename.name
|
||||
) as data:
|
||||
data.total = 4
|
||||
|
||||
with kanta.transaction(action="create", user="u3", extra="Dave (u4)") as data:
|
||||
data.users["u4"] = {"name": "Dave", "role": "user"}
|
||||
|
||||
# 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()
|
||||
logging.getLogger("kanta").setLevel(logging.DEBUG) # show migration diffs
|
||||
asyncio.run(main())
|
||||
|
||||
+6
-2
@@ -215,8 +215,12 @@ def resolve_user_key(value: str) -> str | None:
|
||||
- `kanta.transaction(..., extra="...")` accepts a display-only string that is
|
||||
appended after the action in the header (colored by Kanta); it is never
|
||||
persisted in the `ChangeRecord`.
|
||||
- The header and diff parts can be toggled independently per transaction:
|
||||
`kanta.transaction(..., log={"header": True, "diff": False})`.
|
||||
- `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.
|
||||
|
||||
## Migrations
|
||||
|
||||
|
||||
+9
-4
@@ -320,7 +320,8 @@ class Kanta(Generic[T]):
|
||||
user: str | None = None,
|
||||
extra: str | None = None,
|
||||
mtime: bool | datetime = True,
|
||||
log: bool | logging.Logger | dict[str, bool] = True,
|
||||
log: bool | logging.Logger = True,
|
||||
logdiff: bool = True,
|
||||
):
|
||||
"""Create a transactional mutation context manager.
|
||||
|
||||
@@ -341,9 +342,12 @@ class Kanta(Generic[T]):
|
||||
log: Controls transaction logging. ``True`` (default) uses the
|
||||
``kanta.transaction`` logger. ``False`` suppresses the
|
||||
transaction log. A :class:`~logging.Logger` instance writes
|
||||
output to that logger instead. A dict such as
|
||||
``{"header": True, "diff": False}`` toggles the header and
|
||||
diff parts independently.
|
||||
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.
|
||||
@@ -360,4 +364,5 @@ class Kanta(Generic[T]):
|
||||
extra=extra,
|
||||
mtime=mtime,
|
||||
log=log,
|
||||
logdiff=logdiff,
|
||||
)
|
||||
|
||||
+26
-18
@@ -306,7 +306,6 @@ def log_change(
|
||||
*,
|
||||
logger: logging.Logger = transaction_logger,
|
||||
level: int = logging.INFO,
|
||||
log_header: bool = True,
|
||||
log_diff: bool = True,
|
||||
) -> None:
|
||||
"""Log a database change with pretty-printed diff.
|
||||
@@ -321,30 +320,33 @@ def log_change(
|
||||
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_header: Whether to emit the header line.
|
||||
log_diff: Whether to emit the diff lines.
|
||||
log_diff: Whether to build and emit the diff lines. ``False`` skips
|
||||
diff formatting entirely and only the header is logged.
|
||||
|
||||
Diff lines are emitted on the ``<logger.name>.diff`` child logger, so they
|
||||
can be silenced globally without losing the headers (see
|
||||
:func:`configure_logging`). When the child logger would not emit at the
|
||||
given level, diff formatting is skipped altogether.
|
||||
"""
|
||||
header: str | None = None
|
||||
if log_header:
|
||||
header = format_action_header(action, user, extra)
|
||||
|
||||
diff_lines = format_diff(diff, previous, logfmt) if log_diff else []
|
||||
|
||||
if header is None:
|
||||
for line in diff_lines:
|
||||
logger.log(level, line)
|
||||
return
|
||||
diff_logger = logging.getLogger(f"{logger.name}.diff")
|
||||
diff_lines = (
|
||||
format_diff(diff, previous, logfmt)
|
||||
if log_diff and diff_logger.isEnabledFor(level)
|
||||
else []
|
||||
)
|
||||
header = format_action_header(action, user, extra)
|
||||
|
||||
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)
|
||||
diff_logger.log(level, f"{header}{diff_lines[0]}")
|
||||
return
|
||||
|
||||
logger.log(level, header)
|
||||
for line in diff_lines:
|
||||
diff_logger.log(level, line)
|
||||
|
||||
|
||||
def configure_logging(
|
||||
@@ -353,6 +355,7 @@ def configure_logging(
|
||||
bootstrap: bool = True,
|
||||
migration: bool = True,
|
||||
transaction: bool = True,
|
||||
diff: bool = True,
|
||||
) -> None:
|
||||
"""Configure Kanta's default logging output.
|
||||
|
||||
@@ -366,11 +369,16 @@ 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),
|
||||
|
||||
+6
-14
@@ -23,7 +23,8 @@ def transaction(
|
||||
user: str | None = None,
|
||||
extra: str | None = None,
|
||||
mtime: bool | datetime = True,
|
||||
log: bool | logging.Logger | dict[str, bool] = True,
|
||||
log: bool | logging.Logger = True,
|
||||
logdiff: bool = True,
|
||||
):
|
||||
"""Wrap writes in a transaction and yield the live db object."""
|
||||
if impl.readonly:
|
||||
@@ -83,17 +84,9 @@ def transaction(
|
||||
if resolved is not None:
|
||||
formatted_user = resolved
|
||||
if log is not False:
|
||||
if isinstance(log, dict):
|
||||
log_header = bool(log.get("header", True))
|
||||
log_diff = bool(log.get("diff", True))
|
||||
logger = transaction_logger
|
||||
else:
|
||||
log_header = log_diff = True
|
||||
logger = (
|
||||
log
|
||||
if isinstance(log, logging.Logger)
|
||||
else transaction_logger
|
||||
)
|
||||
logger = (
|
||||
log if isinstance(log, logging.Logger) else transaction_logger
|
||||
)
|
||||
log_change(
|
||||
action,
|
||||
record.diff,
|
||||
@@ -102,8 +95,7 @@ def transaction(
|
||||
extra=extra,
|
||||
logfmt=logfmt,
|
||||
logger=logger,
|
||||
log_header=log_header,
|
||||
log_diff=log_diff,
|
||||
log_diff=logdiff,
|
||||
)
|
||||
except Exception:
|
||||
_logger.warning("Transaction '%s' failed, rolling back changes", action)
|
||||
|
||||
@@ -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"
|
||||
|
||||
+28
-15
@@ -30,10 +30,17 @@ def test_colorize_header_parts_missing_user_and_extra():
|
||||
@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()
|
||||
|
||||
|
||||
@@ -80,30 +87,36 @@ def test_log_change_appends_extra_string(capsys):
|
||||
assert f"{_TARGET}mydb.db{_RESET}" in captured.err
|
||||
|
||||
|
||||
def test_log_change_log_diff_false(capsys):
|
||||
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_log_change_log_header_false(capsys):
|
||||
def test_configure_logging_diff_false(capsys):
|
||||
kanta_logger = logging.getLogger("kanta")
|
||||
kanta_logger.handlers.clear()
|
||||
configure_logging()
|
||||
log_change("update", {"counter": 5}, previous={}, log_header=False)
|
||||
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 "update" not in captured.err
|
||||
assert "counter" in captured.err
|
||||
|
||||
|
||||
def test_log_change_both_disabled_logs_nothing(capsys):
|
||||
kanta_logger = logging.getLogger("kanta")
|
||||
kanta_logger.handlers.clear()
|
||||
configure_logging()
|
||||
log_change("update", {"counter": 5}, previous={}, log_header=False, log_diff=False)
|
||||
captured = capsys.readouterr()
|
||||
assert captured.err == ""
|
||||
|
||||
Reference in New Issue
Block a user