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 "🛢️ x.kantadb created" in err assert "🛢️ x.kantadb migrated v0 -> v1: migrate_v1 (rename)" in err def test_default_emit_strips_ansi_without_color_support(capsys, monkeypatch): """NO_COLOR output contains no ANSI codes; FORCE_COLOR keeps them.""" logging.getLogger("kanta").handlers.clear() configure_logging() monkeypatch.setenv("NO_COLOR", "1") monkeypatch.delenv("FORCE_COLOR", raising=False) emit_event(_change_event(diff={"counter": 1})) err = capsys.readouterr().err assert "\x1b[" not in err assert "counter" in err logging.getLogger("kanta").handlers.clear() configure_logging() monkeypatch.setenv("FORCE_COLOR", "1") monkeypatch.delenv("NO_COLOR", raising=False) emit_event(_change_event(diff={"counter": 1})) assert "\x1b[" in capsys.readouterr().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, monkeypatch ): monkeypatch.setenv("FORCE_COLOR", "1") monkeypatch.delenv("NO_COLOR", raising=False) 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 == "🛢️ x.db created" migrated = LogEvent( kind="migrated", logger=transaction_logger, filename="x.db", from_version=0, to_version=1, migrations=["migrate_v1 (rename)"], ) assert migrated.header == "🛢️ x.db migrated 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)