Implement richer, fully customizable logging; customizable timestamps #1
+12
-11
@@ -225,16 +225,17 @@ def resolve_user_key(value: str) -> str | None:
|
||||
#### Log Emitters
|
||||
|
||||
- Every change-related message Kanta emits (transaction/bootstrap/migration
|
||||
changes, `Created <file>`, migration summaries) 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.
|
||||
changes, `Created <file>`, 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"`), the preferred `logger` and `level`, and all relevant state:
|
||||
`action`, `user`, `extra`, `diff`, `previous`/`current` state dicts, the
|
||||
built `logfmt` chain, and version info for migration events. Pretty
|
||||
`header` and `diff_lines` are lazy properties, built only if accessed.
|
||||
`"migrated"`, `"aborted"`), the preferred `logger` and `level`, 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. Pretty `header` and
|
||||
`diff_lines` are lazy properties, built only if accessed.
|
||||
- `@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
|
||||
@@ -242,8 +243,8 @@ def resolve_user_key(value: str) -> str | None:
|
||||
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 (rollback warnings, integrity errors)
|
||||
do not go through this mechanism.
|
||||
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
|
||||
|
||||
+12
-3
@@ -40,9 +40,10 @@ 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), or ``"migrated"`` (migration
|
||||
summary). ``logger`` and ``level`` are Kanta's preferred destination;
|
||||
a callback may use them, log elsewhere, or not log at all.
|
||||
``"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.
|
||||
@@ -54,6 +55,7 @@ class LogEvent(msgspec.Struct, kw_only=True):
|
||||
action: str | None = None
|
||||
user: str | None = None
|
||||
extra: str | None = None
|
||||
error: BaseException | None = None
|
||||
diff: dict = msgspec.field(default_factory=dict)
|
||||
previous: dict | None = None
|
||||
current: dict | None = None
|
||||
@@ -134,6 +136,13 @@ def default_emit(ev: LogEvent) -> None:
|
||||
)
|
||||
return
|
||||
|
||||
if ev.kind == "aborted":
|
||||
message = str(
|
||||
Line().action(ev.action or "")(f" transaction aborted: {ev.error}")
|
||||
)
|
||||
ev.logger.log(ev.level, message)
|
||||
return
|
||||
|
||||
# kind == "change": diff lines go to the <logger>.diff child logger so
|
||||
# they can be silenced or routed separately from the headers.
|
||||
diff_logger = logging.getLogger(f"{ev.logger.name}.diff")
|
||||
|
||||
+11
-2
@@ -102,8 +102,17 @@ def transaction(
|
||||
),
|
||||
impl.callback_registry.logemit_handlers,
|
||||
)
|
||||
except Exception:
|
||||
_logger.warning("Transaction '%s' failed, rolling back changes", action)
|
||||
except Exception as exc:
|
||||
emit_event(
|
||||
LogEvent(
|
||||
kind="aborted",
|
||||
logger=transaction_logger,
|
||||
level=logging.WARNING,
|
||||
action=action,
|
||||
error=exc,
|
||||
),
|
||||
impl.callback_registry.logemit_handlers,
|
||||
)
|
||||
if impl.transaction_snapshot is not None:
|
||||
impl.data = restore_data_in_place(
|
||||
impl.data,
|
||||
|
||||
@@ -239,3 +239,30 @@ async def test_logmigr_failure_does_not_break_open(tmp_path, format_config):
|
||||
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
|
||||
|
||||
Reference in New Issue
Block a user