feat(activity-log): phase 2 - recorder, actor context, retention, lifecycle

- ActivityRecorder: thread-safe record() (inline on loop, call_soon_threadsafe off-loop), best-effort, fires activity_logged event
- current_actor ContextVar set in verify_api_key (both branches), default system
- ActivityLogRetentionEngine: prune loop (max_days+max_entries), settings persistence, rehydrates recorder.enabled on startup
- lifespan wiring: server.shutting_down recorded first on shutdown, retention stop before db.close
- events-ws.ts allowlist + parity; DI getters + module accessor; 62 new tests
This commit is contained in:
2026-06-09 18:10:27 +03:00
parent 1ac4a0f66d
commit 726f39e2ba
14 changed files with 2037 additions and 16 deletions
@@ -0,0 +1,312 @@
"""Unit tests for ActivityLogRetentionEngine (Phase 2).
Coverage targets
----------------
- Prunes entries older than max_days.
- Prunes entries when count exceeds max_entries.
- Settings round-trip: persist to DB, reload on construction.
- Disabling logs the ``audit_log.disabled`` event via the recorder BEFORE
the flag takes effect.
- ``start()`` / ``stop()`` lifecycle does not raise.
- Loop starts only when ``enabled=True``; does not start when ``enabled=False``.
"""
from __future__ import annotations
import asyncio
from datetime import datetime, timedelta, timezone
from unittest.mock import MagicMock
from ledgrab.core.activity_log.recorder import ActivityRecorder
from ledgrab.core.activity_log.retention import (
DEFAULT_SETTINGS,
ActivityLogRetentionEngine,
)
from ledgrab.storage.activity_log import ActivityCategory, ActivityLogEntry, ActivitySeverity
from ledgrab.storage.activity_log_repository import ActivityLogRepository
from ledgrab.storage.database import Database
# ---------------------------------------------------------------------------
# Helpers
# ---------------------------------------------------------------------------
def _make_entry(
*,
action: str = "test.action",
ts: datetime | None = None,
) -> ActivityLogEntry:
from datetime import timezone
import uuid
return ActivityLogEntry(
id="al_" + uuid.uuid4().hex[:8],
ts=ts or datetime.now(timezone.utc),
category=ActivityCategory.SYSTEM,
action=action,
severity=ActivitySeverity.INFO,
actor="system",
message="test",
)
def _repo_and_db(tmp_db: Database):
"""Return (ActivityLogRepository, Database) backed by a temp DB."""
repo = ActivityLogRepository(tmp_db)
return repo, tmp_db
def _mock_recorder() -> ActivityRecorder:
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
return recorder
# ---------------------------------------------------------------------------
# Settings persistence
# ---------------------------------------------------------------------------
def test_default_settings(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
s = engine.get_settings()
assert s == DEFAULT_SETTINGS
def test_settings_round_trip(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
asyncio.run(engine.update_settings(enabled=True, max_days=30, max_entries=5000))
s = engine.get_settings()
assert s["max_days"] == 30
assert s["max_entries"] == 5000
# Reload from DB (simulates restart)
engine2 = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
s2 = engine2.get_settings()
assert s2["max_days"] == 30
assert s2["max_entries"] == 5000
# ---------------------------------------------------------------------------
# Pruning
# ---------------------------------------------------------------------------
def test_prune_by_age(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
now = datetime.now(timezone.utc)
old_ts = now - timedelta(days=100)
recent_ts = now - timedelta(days=5)
repo.record(_make_entry(ts=old_ts))
repo.record(_make_entry(ts=recent_ts))
assert repo.count() == 2
# Simulate prune with max_days=90
asyncio.run(engine.update_settings(enabled=True, max_days=90, max_entries=0))
engine._prune()
# Only the old entry should be gone; 0 for max_entries means no count cap
assert repo.count() == 1
entries = repo.query(
filters=__import__(
"ledgrab.storage.activity_log", fromlist=["ActivityLogFilters"]
).ActivityLogFilters()
)
assert entries[0].ts.date() == recent_ts.date()
def test_prune_by_max_entries(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
for _ in range(10):
repo.record(_make_entry())
assert repo.count() == 10
asyncio.run(engine.update_settings(enabled=True, max_days=0, max_entries=5))
engine._prune()
assert repo.count() == 5
def test_prune_disabled_is_noop(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
for _ in range(5):
repo.record(_make_entry())
# Disable engine then force a prune call
asyncio.run(engine.update_settings(enabled=False, max_days=1, max_entries=1))
engine._prune() # should be a no-op since enabled=False
assert repo.count() == 5
# ---------------------------------------------------------------------------
# Disabling records the disable event
# ---------------------------------------------------------------------------
def test_disable_records_disable_event(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
# Engine starts enabled (DEFAULT_SETTINGS["enabled"] == True)
asyncio.run(engine.update_settings(enabled=False, max_days=90, max_entries=20000))
# recorder.record must have been called with the disable action
recorder.record.assert_called_once()
kwargs = recorder.record.call_args
assert kwargs.kwargs.get("action") == "audit_log.disabled" or (
len(kwargs.args) > 1 and kwargs.args[1] == "audit_log.disabled"
)
# The bypass flag must be set so the disabled event gets through
assert kwargs.kwargs.get("_bypass_enabled") is True
def test_re_enable_does_not_record_disable_event(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
# Disable first
asyncio.run(engine.update_settings(enabled=False, max_days=90, max_entries=20000))
call_count_after_disable = recorder.record.call_count
# Re-enable — should NOT call recorder again
asyncio.run(engine.update_settings(enabled=True, max_days=90, max_entries=20000))
assert recorder.record.call_count == call_count_after_disable
# ---------------------------------------------------------------------------
# Lifecycle: start / stop
# ---------------------------------------------------------------------------
def test_start_stop_does_not_raise(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
async def _run():
await engine.start()
await engine.stop()
asyncio.run(_run())
def test_start_disabled_does_not_create_task(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
# Persist disabled setting
db.set_setting("activity_log", {**DEFAULT_SETTINGS, "enabled": False})
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
async def _run():
await engine.start()
assert engine._task is None
await engine.stop()
asyncio.run(_run())
def test_start_enabled_creates_task(tmp_db):
repo, db = _repo_and_db(tmp_db)
recorder = _mock_recorder()
engine = ActivityLogRetentionEngine(repo=repo, db=db, recorder=recorder)
# DEFAULT_SETTINGS has enabled=True
async def _run():
await engine.start()
assert engine._task is not None
await engine.stop()
assert engine._task is None
asyncio.run(_run())
# ---------------------------------------------------------------------------
# Regression: recorder.enabled rehydrated from persisted settings on __init__
# ---------------------------------------------------------------------------
def test_recorder_enabled_rehydrated_from_persisted_disabled(tmp_db):
"""Engine.__init__ must propagate persisted enabled=False to recorder.
If a user disabled the activity log and the server restarts, the recorder
must start in the disabled state — not its hardcoded default of True.
"""
from unittest.mock import MagicMock
from ledgrab.core.processing.processor_manager import ProcessorManager
repo, db = _repo_and_db(tmp_db)
# Persist enabled=False before constructing the engine.
db.set_setting("activity_log", {**DEFAULT_SETTINGS, "enabled": False})
# Use a real ActivityRecorder (not a mock) so we can observe its state.
mock_pm = MagicMock(spec=ProcessorManager)
real_recorder = ActivityRecorder(repo=repo, processor_manager=mock_pm)
ActivityLogRetentionEngine(repo=repo, db=db, recorder=real_recorder)
assert real_recorder.enabled is False, (
"recorder.enabled should be False after constructing the engine "
"over a DB where enabled=False was persisted"
)
def test_recorder_enabled_rehydrated_from_persisted_enabled(tmp_db):
"""Engine.__init__ leaves recorder enabled when persisted setting is True."""
from unittest.mock import MagicMock
from ledgrab.core.processing.processor_manager import ProcessorManager
repo, db = _repo_and_db(tmp_db)
# Persist enabled=True explicitly.
db.set_setting("activity_log", {**DEFAULT_SETTINGS, "enabled": True})
mock_pm = MagicMock(spec=ProcessorManager)
real_recorder = ActivityRecorder(repo=repo, processor_manager=mock_pm)
ActivityLogRetentionEngine(repo=repo, db=db, recorder=real_recorder)
assert real_recorder.enabled is True, (
"recorder.enabled should be True after constructing the engine "
"over a DB where enabled=True was persisted"
)
def test_recorder_enabled_defaults_to_true_when_no_persisted_setting(tmp_db):
"""Engine.__init__ leaves recorder enabled when no setting has been persisted."""
from unittest.mock import MagicMock
from ledgrab.core.processing.processor_manager import ProcessorManager
repo, db = _repo_and_db(tmp_db)
# No db.set_setting call — DB has no activity_log setting yet.
mock_pm = MagicMock(spec=ProcessorManager)
real_recorder = ActivityRecorder(repo=repo, processor_manager=mock_pm)
ActivityLogRetentionEngine(repo=repo, db=db, recorder=real_recorder)
assert (
real_recorder.enabled is True
), "recorder.enabled should default to True when no setting is persisted"
+256
View File
@@ -0,0 +1,256 @@
"""Unit tests for ActivityRecorder (Phase 2).
Coverage targets
----------------
- record() persists an entry AND fires ``activity_logged`` via fire_event.
- actor resolves from the ``current_actor`` ContextVar; defaults to ``"system"``.
- Failure in repo.record() does NOT raise into the caller.
- Cross-thread record() from a threading.Thread routes through the event loop
and persists.
- ``enabled=False`` makes record() a no-op (except ``_bypass_enabled``).
- ``entry_to_dict`` produces the expected shape.
"""
from __future__ import annotations
import asyncio
import threading
from unittest.mock import MagicMock
from ledgrab.core.activity_log.context import current_actor
from ledgrab.core.activity_log.recorder import ActivityRecorder, entry_to_dict
from ledgrab.storage.activity_log import ActivityCategory, ActivityLogEntry, ActivitySeverity
# ---------------------------------------------------------------------------
# Helpers / fixtures
# ---------------------------------------------------------------------------
def _make_recorder(
*,
fail_repo: bool = False,
loop: asyncio.AbstractEventLoop | None = None,
) -> tuple[ActivityRecorder, list, list]:
"""Return (recorder, persisted_entries, fired_events)."""
repo = MagicMock()
persisted: list[ActivityLogEntry] = []
if fail_repo:
repo.record.side_effect = RuntimeError("DB exploded")
else:
repo.record.side_effect = lambda entry: persisted.append(entry)
pm = MagicMock()
fired: list[dict] = []
pm.fire_event.side_effect = lambda evt: fired.append(evt)
recorder = ActivityRecorder(repo, pm, loop=loop)
return recorder, persisted, fired
# ---------------------------------------------------------------------------
# Basic persistence + event emit
# ---------------------------------------------------------------------------
def test_record_persists_entry():
recorder, persisted, fired = _make_recorder()
recorder.record(
category=ActivityCategory.SYSTEM,
action="test.action",
message="hello",
)
assert len(persisted) == 1
entry = persisted[0]
assert entry.category == ActivityCategory.SYSTEM
assert entry.action == "test.action"
assert entry.message == "hello"
assert entry.id.startswith("al_")
def test_record_fires_activity_logged_event():
recorder, persisted, fired = _make_recorder()
recorder.record(
category=ActivityCategory.AUTH,
action="auth.login",
message="user signed in",
)
assert len(fired) == 1
evt = fired[0]
assert evt["type"] == "activity_logged"
assert "entry" in evt
assert evt["entry"]["action"] == "auth.login"
def test_record_default_severity_is_info():
recorder, persisted, _ = _make_recorder()
recorder.record(category=ActivityCategory.SYSTEM, action="x", message="m")
assert persisted[0].severity == ActivitySeverity.INFO
def test_record_custom_fields():
recorder, persisted, _ = _make_recorder()
recorder.record(
category=ActivityCategory.ENTITY,
action="entity.created",
severity=ActivitySeverity.WARNING,
entity_type="output_target",
entity_id="ot_abc123",
entity_name="My strip",
message="created",
metadata={"key": "val"},
)
e = persisted[0]
assert e.severity == ActivitySeverity.WARNING
assert e.entity_type == "output_target"
assert e.entity_id == "ot_abc123"
assert e.entity_name == "My strip"
assert e.metadata == {"key": "val"}
# ---------------------------------------------------------------------------
# Actor resolution from ContextVar
# ---------------------------------------------------------------------------
def test_actor_defaults_to_system():
recorder, persisted, _ = _make_recorder()
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
assert persisted[0].actor == "system"
def test_actor_resolved_from_contextvar():
recorder, persisted, _ = _make_recorder()
token = current_actor.set("homeassistant")
try:
recorder.record(category=ActivityCategory.AUTH, action="b", message="m")
finally:
current_actor.reset(token)
assert persisted[0].actor == "homeassistant"
def test_actor_explicit_overrides_contextvar():
recorder, persisted, _ = _make_recorder()
token = current_actor.set("homeassistant")
try:
recorder.record(
category=ActivityCategory.SYSTEM,
action="c",
message="m",
actor="explicit_actor",
)
finally:
current_actor.reset(token)
assert persisted[0].actor == "explicit_actor"
# ---------------------------------------------------------------------------
# Failure isolation — repo failure must not raise into caller
# ---------------------------------------------------------------------------
def test_repo_failure_does_not_raise():
recorder, persisted, fired = _make_recorder(fail_repo=True)
# Must not raise
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
# No event emitted when persist failed
assert fired == []
# ---------------------------------------------------------------------------
# enabled flag
# ---------------------------------------------------------------------------
def test_disabled_recorder_is_noop():
recorder, persisted, fired = _make_recorder()
recorder.enabled = False
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
assert persisted == []
assert fired == []
def test_bypass_enabled_flag_records_even_when_disabled():
recorder, persisted, fired = _make_recorder()
recorder.enabled = False
recorder.record(
category=ActivityCategory.SYSTEM,
action="audit_log.disabled",
message="disabled",
_bypass_enabled=True,
)
assert len(persisted) == 1
# ---------------------------------------------------------------------------
# entry_to_dict helper
# ---------------------------------------------------------------------------
def test_entry_to_dict_shape():
from datetime import datetime, timezone
entry = ActivityLogEntry(
id="al_aabbccdd",
ts=datetime(2026, 1, 2, 3, 4, 5, tzinfo=timezone.utc),
category="system",
action="test",
severity="info",
actor="system",
message="hello",
metadata={"x": 1},
)
d = entry_to_dict(entry)
assert set(d.keys()) == {
"id",
"ts",
"category",
"action",
"severity",
"actor",
"entity_type",
"entity_id",
"entity_name",
"message",
"metadata",
}
assert d["metadata"] == {"x": 1} # real dict, not JSON string
assert d["ts"].startswith("2026-01-02T03:04:05")
# ---------------------------------------------------------------------------
# Cross-thread record() — routes through the event loop and persists
# ---------------------------------------------------------------------------
def test_cross_thread_record_routes_through_loop():
"""record() called from a non-loop thread marshals via call_soon_threadsafe."""
async def _run():
recorder, persisted, fired = _make_recorder(loop=asyncio.get_running_loop())
recorder.ensure_loop()
done = threading.Event()
def _thread_body():
recorder.record(
category=ActivityCategory.DEVICE,
action="device.discovered",
message="found it",
)
done.set()
t = threading.Thread(target=_thread_body)
t.start()
t.join(timeout=2.0)
# Give the scheduled callback a chance to run on the loop.
await asyncio.sleep(0.05)
assert len(persisted) == 1, f"Expected 1 entry, got {persisted}"
assert persisted[0].action == "device.discovered"
assert len(fired) == 1
assert fired[0]["type"] == "activity_logged"
asyncio.run(_run())
@@ -0,0 +1,778 @@
"""Adversarial / edge-case tests for ActivityRecorder and ActivityLogRetentionEngine.
Derive expected behaviour from the acceptance criteria in
plans/activity-log/phase-2-recorder-retention.md — NOT from what the code does.
A failing test is a bug found in the implementation.
Coverage areas
--------------
1. Thread-safety / marshaling — record() from a non-loop thread routes via
call_soon_threadsafe; record() from the loop thread writes inline.
Neither path raises into the caller even when the loop is closed.
2. Best-effort / never-raises — repo.record raises → no exception escapes,
no event emitted; fire_event raises → no exception escapes, entry still
persisted (order: persist THEN emit).
3. Actor resolution — defaults "system"; ContextVar wins when set;
explicit actor= overrides ContextVar; no cross-context leakage (fresh
ContextVar copy does not see a previous set).
4. enabled flag — disabled → NO-OP (nothing persisted, no event);
_bypass_enabled=True → still records despite enabled=False.
5. entry_to_dict / payload — exactly 11 keys; ts is ISO-8601 string;
metadata is a real dict; activity_logged payload shape is frozen.
6. Retention engine — update_settings persists and round-trips;
_prune calls repo.prune with correct before_ts / max_entries;
disabling records exactly one disable event BEFORE recording stops;
subsequent normal record after disable is a no-op;
start() then stop() cancels task cleanly;
stop() without prior start() is safe.
7. Lazy loop capture — recorder built before the loop is running still
works after the loop starts (no explicit loop= argument).
"""
from __future__ import annotations
import asyncio
import contextvars
import threading
import uuid
from datetime import datetime, timedelta, timezone
from unittest.mock import MagicMock
from ledgrab.core.activity_log.context import current_actor
from ledgrab.core.activity_log.recorder import (
ActivityRecorder,
entry_to_dict,
get_module_recorder,
set_module_recorder,
)
from ledgrab.core.activity_log.retention import (
DEFAULT_SETTINGS,
ActivityLogRetentionEngine,
)
from ledgrab.storage.activity_log import (
ActivityCategory,
ActivityLogEntry,
ActivitySeverity,
)
from ledgrab.storage.activity_log_repository import ActivityLogRepository
# ---------------------------------------------------------------------------
# Shared helpers
# ---------------------------------------------------------------------------
def _make_recorder(
*,
fail_repo: bool = False,
fail_pm: bool = False,
loop: asyncio.AbstractEventLoop | None = None,
) -> tuple[ActivityRecorder, list[ActivityLogEntry], list[dict]]:
"""Return (recorder, persisted_entries, fired_events) — pure mocks."""
repo = MagicMock()
persisted: list[ActivityLogEntry] = []
if fail_repo:
repo.record.side_effect = RuntimeError("DB exploded")
else:
repo.record.side_effect = lambda entry: persisted.append(entry)
pm = MagicMock()
fired: list[dict] = []
if fail_pm:
pm.fire_event.side_effect = RuntimeError("PM exploded")
else:
pm.fire_event.side_effect = lambda evt: fired.append(evt)
recorder = ActivityRecorder(repo, pm, loop=loop)
return recorder, persisted, fired
def _make_entry(action: str = "test.action") -> ActivityLogEntry:
return ActivityLogEntry(
id="al_" + uuid.uuid4().hex[:8],
ts=datetime.now(timezone.utc),
category=ActivityCategory.SYSTEM,
action=action,
severity=ActivitySeverity.INFO,
actor="system",
message="test",
)
# ---------------------------------------------------------------------------
# 1. Thread-safety / marshaling
# ---------------------------------------------------------------------------
def test_cross_thread_write_goes_via_call_soon_threadsafe():
"""record() from a non-loop thread must marshal onto the loop, not write inline."""
async def _run():
loop = asyncio.get_running_loop()
recorder, persisted, fired = _make_recorder(loop=loop)
# Ensure the recorder knows the loop.
recorder.ensure_loop()
thread_saw_persisted_count: list[int] = []
def _thread_body():
# Nothing should be persisted synchronously in this thread —
# the write must be deferred to the loop via call_soon_threadsafe.
recorder.record(
category=ActivityCategory.DEVICE,
action="device.discovered",
message="zeroconf found it",
)
# Capture how many entries are persisted synchronously right after the call.
thread_saw_persisted_count.append(len(persisted))
t = threading.Thread(target=_thread_body)
t.start()
t.join(timeout=2.0)
assert not t.is_alive(), "thread did not finish in time"
# The thread's synchronous view must see 0 — the actual write is deferred.
assert thread_saw_persisted_count[0] == 0, (
"write was not deferred: record() persisted synchronously on the "
"calling thread instead of marshaling to the loop"
)
# Give the loop a tick to drain the call_soon_threadsafe callback.
await asyncio.sleep(0.05)
assert len(persisted) == 1, f"entry not persisted after loop tick: {persisted}"
assert persisted[0].action == "device.discovered"
assert len(fired) == 1
assert fired[0]["type"] == "activity_logged"
asyncio.run(_run())
def test_loop_thread_write_is_inline():
"""record() called from the loop thread writes without call_soon_threadsafe."""
call_soon_threadsafe_calls: list = []
async def _run():
loop = asyncio.get_running_loop()
# Monkeypatch call_soon_threadsafe to detect if it is used.
original_csst = loop.call_soon_threadsafe
loop.call_soon_threadsafe = lambda *a, **kw: call_soon_threadsafe_calls.append(a) or original_csst(*a, **kw) # type: ignore[method-assign]
try:
recorder, persisted, fired = _make_recorder(loop=loop)
recorder.ensure_loop()
recorder.record(
category=ActivityCategory.SYSTEM,
action="system.startup",
message="loop thread write",
)
# No yield — synchronous within the coroutine.
assert len(persisted) == 1, "inline write did not happen synchronously"
assert call_soon_threadsafe_calls == [], (
"call_soon_threadsafe was invoked from the loop thread — "
"should write inline instead"
)
finally:
loop.call_soon_threadsafe = original_csst # type: ignore[method-assign]
asyncio.run(_run())
def test_cross_thread_closed_loop_does_not_raise():
"""record() from a thread after the loop closes must log a warning, not raise."""
loop = asyncio.new_event_loop()
recorder, persisted, fired = _make_recorder(loop=loop)
# Close the loop immediately — simulate a test teardown race.
loop.close()
# This must not raise.
recorder.record(
category=ActivityCategory.SYSTEM,
action="closed.loop.test",
message="should not raise",
)
# The entry may or may not be persisted (the closed-loop path drops it),
# but the important contract is: no exception propagates.
def test_no_loop_falls_back_to_synchronous_write():
"""record() with no loop and no running loop writes synchronously."""
recorder, persisted, fired = _make_recorder(loop=None)
# No loop is running here (plain synchronous test).
recorder.record(
category=ActivityCategory.SYSTEM,
action="no.loop.write",
message="synchronous fallback",
)
assert len(persisted) == 1
assert len(fired) == 1
# ---------------------------------------------------------------------------
# 2. Best-effort / never-raises
# ---------------------------------------------------------------------------
def test_repo_failure_does_not_raise_and_suppresses_fire_event():
"""repo.record raises → no exception propagates AND fire_event is NOT called."""
recorder, persisted, fired = _make_recorder(fail_repo=True)
# Must not raise.
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
# No event must be emitted for an entry that failed to persist.
assert fired == [], (
"fire_event was called even though repo.record failed — "
"the event would reference an entry that was never stored"
)
def test_fire_event_failure_does_not_raise_and_entry_is_persisted():
"""fire_event raises → no exception propagates AND the entry IS persisted.
Order: persist THEN emit. An emit failure must not roll back the persist.
"""
recorder, persisted, fired = _make_recorder(fail_pm=True)
# Must not raise.
recorder.record(category=ActivityCategory.SYSTEM, action="b", message="m")
# Entry must have been persisted before the emit attempt.
assert (
len(persisted) == 1
), "entry was not persisted — fire_event failure retroactively erased it"
def test_both_failures_do_not_raise():
"""Even when both repo AND fire_event raise, record() must not propagate."""
recorder, persisted, fired = _make_recorder(fail_repo=True, fail_pm=True)
recorder.record(category=ActivityCategory.SYSTEM, action="c", message="m")
# Nothing persisted, nothing fired — but absolutely no exception.
# ---------------------------------------------------------------------------
# 3. Actor resolution / ContextVar isolation
# ---------------------------------------------------------------------------
def test_actor_defaults_to_system_when_contextvar_unset():
"""When no actor arg and ContextVar at default, actor must be 'system'."""
recorder, persisted, _ = _make_recorder()
# Make sure the ContextVar is at its default.
token = current_actor.set("system")
current_actor.reset(token)
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
assert persisted[0].actor == "system"
def test_explicit_actor_overrides_contextvar():
"""Explicit actor= argument wins over the ContextVar value."""
recorder, persisted, _ = _make_recorder()
token = current_actor.set("api_user")
try:
recorder.record(
category=ActivityCategory.AUTH,
action="auth.login",
message="explicit",
actor="override_actor",
)
finally:
current_actor.reset(token)
assert (
persisted[0].actor == "override_actor"
), "explicit actor= was ignored; ContextVar won over explicit arg"
def test_contextvar_value_used_when_set():
"""When current_actor ContextVar is set, recorder picks it up."""
recorder, persisted, _ = _make_recorder()
token = current_actor.set("mobile_client")
try:
recorder.record(category=ActivityCategory.ENTITY, action="e.created", message="m")
finally:
current_actor.reset(token)
assert persisted[0].actor == "mobile_client"
def test_no_cross_context_leakage_via_copy_context():
"""ContextVar set in one context does not bleed into an independent copy."""
# Simulate request-1 setting the actor.
ctx_req1 = contextvars.copy_context()
def _request1():
current_actor.set("user_alice")
ctx_req1.run(_request1)
# Simulate request-2 in a fresh copy — must not see user_alice.
ctx_req2 = contextvars.copy_context()
def _request2():
return current_actor.get()
actor_in_req2 = ctx_req2.run(_request2)
assert actor_in_req2 == "system", (
f"Cross-context leakage: request-2 saw actor '{actor_in_req2}' "
"from request-1 instead of the default 'system'"
)
def test_no_cross_request_leakage_sequential_records():
"""Two sequential simulated requests must not share ContextVar state."""
recorder, persisted, _ = _make_recorder()
# Request 1: set actor, record, reset.
token1 = current_actor.set("admin_user")
try:
recorder.record(category=ActivityCategory.AUTH, action="login", message="req1")
finally:
current_actor.reset(token1)
# Request 2: no actor set — must fall back to "system".
recorder.record(category=ActivityCategory.SYSTEM, action="heartbeat", message="req2")
assert persisted[0].actor == "admin_user"
assert persisted[1].actor == "system", (
f"Request-2 actor was '{persisted[1].actor}' instead of 'system'"
"ContextVar from request-1 leaked into request-2"
)
# ---------------------------------------------------------------------------
# 4. enabled flag
# ---------------------------------------------------------------------------
def test_disabled_record_is_noop_nothing_persisted():
"""enabled=False → record() returns immediately; nothing persisted."""
recorder, persisted, fired = _make_recorder()
recorder.enabled = False
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
assert persisted == [], "disabled recorder should not persist"
assert fired == [], "disabled recorder should not fire events"
def test_disabled_record_bypass_enabled_still_records():
"""_bypass_enabled=True bypasses the enabled=False guard."""
recorder, persisted, fired = _make_recorder()
recorder.enabled = False
recorder.record(
category=ActivityCategory.SYSTEM,
action="audit_log.disabled",
message="final entry before disable",
_bypass_enabled=True,
)
assert len(persisted) == 1, "_bypass_enabled=True should still persist"
assert len(fired) == 1, "_bypass_enabled=True should still fire the event"
def test_bypass_enabled_false_with_enabled_true_is_normal_record():
"""_bypass_enabled=False and enabled=True → normal record (regression guard)."""
recorder, persisted, fired = _make_recorder()
recorder.enabled = True
recorder.record(
category=ActivityCategory.SYSTEM,
action="normal",
message="m",
_bypass_enabled=False,
)
assert len(persisted) == 1
assert len(fired) == 1
# ---------------------------------------------------------------------------
# 5. entry_to_dict / payload shape
# ---------------------------------------------------------------------------
_EXPECTED_KEYS = frozenset(
{
"id",
"ts",
"category",
"action",
"severity",
"actor",
"entity_type",
"entity_id",
"entity_name",
"message",
"metadata",
}
)
def test_entry_to_dict_has_exactly_11_keys():
"""entry_to_dict must return a dict with exactly the 11 frozen keys."""
d = entry_to_dict(_make_entry())
assert set(d.keys()) == _EXPECTED_KEYS, (
f"Key mismatch.\n Missing: {_EXPECTED_KEYS - set(d.keys())}\n"
f" Extra: {set(d.keys()) - _EXPECTED_KEYS}"
)
def test_entry_to_dict_ts_is_iso8601_string():
"""ts must be an ISO-8601 string, not a datetime object."""
entry = _make_entry()
d = entry_to_dict(entry)
assert isinstance(d["ts"], str), f"ts is {type(d['ts'])}, expected str"
# Must round-trip through fromisoformat without error.
parsed = datetime.fromisoformat(d["ts"])
assert parsed.tzinfo is not None, "ts ISO string has no timezone info"
def test_entry_to_dict_metadata_is_real_dict_not_json_string():
"""metadata must be a dict, not a JSON-encoded string."""
entry = ActivityLogEntry(
id="al_aabbccdd",
ts=datetime.now(timezone.utc),
category=ActivityCategory.SYSTEM,
action="test",
severity=ActivitySeverity.INFO,
actor="system",
message="hello",
metadata={"nested": {"key": 42}, "list": [1, 2, 3]},
)
d = entry_to_dict(entry)
assert isinstance(
d["metadata"], dict
), f"metadata is {type(d['metadata'])}, expected dict (not a JSON string)"
assert d["metadata"] == {"nested": {"key": 42}, "list": [1, 2, 3]}
def test_activity_logged_event_payload_shape():
"""The fired event must match the frozen payload shape from the handoff doc."""
recorder, persisted, fired = _make_recorder()
recorder.record(
category=ActivityCategory.AUTH,
action="auth.login",
severity=ActivitySeverity.WARNING,
actor="api_user",
entity_type="session",
entity_id="sess_001",
entity_name="admin session",
message="user signed in",
metadata={"ip": "127.0.0.1"},
)
assert len(fired) == 1
evt = fired[0]
assert evt.get("type") == "activity_logged", f"event type wrong: {evt.get('type')!r}"
entry_dict = evt.get("entry")
assert isinstance(entry_dict, dict), "event 'entry' must be a dict"
assert set(entry_dict.keys()) == _EXPECTED_KEYS
assert entry_dict["actor"] == "api_user"
assert entry_dict["entity_type"] == "session"
assert entry_dict["metadata"] == {"ip": "127.0.0.1"}
assert isinstance(entry_dict["metadata"], dict), "metadata in event must be a dict"
def test_entry_id_format():
"""Entry IDs must be 'al_' followed by 8 hex characters."""
recorder, persisted, _ = _make_recorder()
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
entry_id = persisted[0].id
assert entry_id.startswith("al_"), f"id does not start with 'al_': {entry_id!r}"
suffix = entry_id[3:]
assert len(suffix) == 8, f"id suffix length is {len(suffix)}, expected 8: {entry_id!r}"
assert all(c in "0123456789abcdef" for c in suffix), f"id suffix is not hex: {suffix!r}"
def test_entry_ts_is_utc():
"""Recorded entry ts must be timezone-aware UTC."""
recorder, persisted, _ = _make_recorder()
recorder.record(category=ActivityCategory.SYSTEM, action="a", message="m")
ts = persisted[0].ts
assert ts.tzinfo is not None, "ts has no timezone info"
# Must be within 5 seconds of now (sanity check).
delta = abs((datetime.now(timezone.utc) - ts).total_seconds())
assert delta < 5, f"ts is {delta:.1f}s away from now — suspiciously stale"
# ---------------------------------------------------------------------------
# 6. Retention engine
# ---------------------------------------------------------------------------
def test_retention_update_settings_persists_to_db(tmp_db):
"""update_settings must persist to DB so a fresh engine reload picks it up."""
repo = ActivityLogRepository(tmp_db)
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
asyncio.run(engine.update_settings(enabled=True, max_days=14, max_entries=500))
# Reload from DB — simulates server restart.
engine2 = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
s = engine2.get_settings()
assert s["max_days"] == 14, f"max_days not persisted: {s}"
assert s["max_entries"] == 500, f"max_entries not persisted: {s}"
assert s["enabled"] is True
def test_retention_prune_passes_correct_before_ts(tmp_db):
"""_prune must call repo.prune with before_ts ≈ now - max_days."""
repo = MagicMock()
repo.prune.return_value = 0
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
# Patch settings directly (don't go through update_settings to avoid task side-effects).
engine._settings = {"enabled": True, "max_days": 30, "max_entries": 0}
before = datetime.now(timezone.utc)
engine._prune()
after = datetime.now(timezone.utc)
repo.prune.assert_called_once()
kwargs = repo.prune.call_args.kwargs
before_ts = kwargs.get("before_ts")
assert before_ts is not None, "_prune called repo.prune without before_ts"
expected_min = before - timedelta(days=30, seconds=1)
expected_max = after - timedelta(days=30) + timedelta(seconds=1)
assert expected_min <= before_ts <= expected_max, (
f"before_ts {before_ts} is not near now - 30 days "
f"(expected [{expected_min}, {expected_max}])"
)
def test_retention_prune_passes_max_entries(tmp_db):
"""_prune must forward max_entries from settings to repo.prune."""
repo = MagicMock()
repo.prune.return_value = 0
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
engine._settings = {"enabled": True, "max_days": 0, "max_entries": 9999}
engine._prune()
kwargs = repo.prune.call_args.kwargs
assert kwargs.get("max_entries") == 9999, f"max_entries not forwarded: {kwargs}"
def test_retention_prune_zero_max_entries_means_no_count_cap(tmp_db):
"""max_entries=0 should pass None (no count cap) to repo.prune."""
repo = MagicMock()
repo.prune.return_value = 0
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
engine._settings = {"enabled": True, "max_days": 0, "max_entries": 0}
engine._prune()
kwargs = repo.prune.call_args.kwargs
assert (
kwargs.get("max_entries") is None
), f"max_entries=0 should map to None (no cap), got {kwargs.get('max_entries')!r}"
def test_retention_disable_records_exactly_one_disable_event_with_bypass(tmp_db):
"""Disabling via update_settings records exactly one 'audit_log.disabled' event
with _bypass_enabled=True BEFORE the enabled flag is set to False."""
repo = ActivityLogRepository(tmp_db)
# Use a real recorder backed by repo to verify ordering.
pm = MagicMock()
pm.fire_event.return_value = None
real_recorder = ActivityRecorder(repo, pm)
real_recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=real_recorder)
# Disable — should record the event before flipping the flag.
asyncio.run(engine.update_settings(enabled=False, max_days=90, max_entries=20000))
# The disable event must be in the DB (persisted before the flag flipped).
entries = repo.query(
__import__(
"ledgrab.storage.activity_log",
fromlist=["ActivityLogFilters"],
).ActivityLogFilters()
)
disable_events = [e for e in entries if e.action == "audit_log.disabled"]
assert len(disable_events) == 1, f"Expected exactly 1 disable event, got {len(disable_events)}"
# After disabling, a normal record must be a no-op.
real_recorder.record(
category=ActivityCategory.SYSTEM,
action="should.not.appear",
message="this should be dropped",
)
entries_after = repo.query(
__import__(
"ledgrab.storage.activity_log",
fromlist=["ActivityLogFilters"],
).ActivityLogFilters()
)
post_disable_actions = [e.action for e in entries_after if e.action != "audit_log.disabled"]
assert post_disable_actions == [], f"Entries appeared after disable: {post_disable_actions}"
def test_retention_disable_does_not_record_event_when_already_disabled(tmp_db):
"""update_settings(enabled=False) when already disabled must NOT record a second event."""
repo = ActivityLogRepository(tmp_db)
pm = MagicMock()
pm.fire_event.return_value = None
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
# First disable.
asyncio.run(engine.update_settings(enabled=False, max_days=90, max_entries=20000))
first_count = recorder.record.call_count
# Second disable — must NOT record another event.
asyncio.run(engine.update_settings(enabled=False, max_days=90, max_entries=20000))
assert (
recorder.record.call_count == first_count
), "A second disable call recorded an extra event when already disabled"
async def test_retention_start_stop_cancels_task_cleanly(tmp_db):
"""start() then stop() must cancel the task and leave _task=None.
After stop(), the task has been requested to cancel and _task is None.
The cancellation may still be 'in-flight' on the event loop (status:
'cancelling') until the next tick; we yield once to let the event loop
process the CancelledError and confirm task.done() is True.
"""
repo = ActivityLogRepository(tmp_db)
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
await engine.start()
task = engine._task
assert task is not None, "start() did not create a task"
assert not task.done(), "task completed immediately — should be sleeping"
await engine.stop()
# _task cleared immediately.
assert engine._task is None, "_task was not cleared to None after stop()"
# Give the event loop one tick to process the CancelledError.
await asyncio.sleep(0)
assert task.done(), (
"task is still running after stop() + one event loop tick — "
"stop() did not cancel the task"
)
async def test_retention_stop_without_start_is_safe(tmp_db):
"""stop() without a prior start() must not raise."""
repo = ActivityLogRepository(tmp_db)
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
assert engine._task is None
# Must not raise.
await engine.stop()
assert engine._task is None
async def test_retention_start_disabled_no_task(tmp_db):
"""start() when enabled=False must not create a task."""
tmp_db.set_setting("activity_log", {**DEFAULT_SETTINGS, "enabled": False})
repo = ActivityLogRepository(tmp_db)
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = False
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
await engine.start()
assert engine._task is None, "task was created even though engine is disabled"
await engine.stop()
async def test_retention_max_days_boundary(tmp_db):
"""max_days ≤ 0 should not pass a before_ts to repo.prune (no age cap)."""
repo = MagicMock()
repo.prune.return_value = 0
recorder = MagicMock(spec=ActivityRecorder)
recorder.enabled = True
engine = ActivityLogRetentionEngine(repo=repo, db=tmp_db, recorder=recorder)
engine._settings = {"enabled": True, "max_days": 0, "max_entries": 0}
engine._prune()
kwargs = repo.prune.call_args.kwargs
assert (
kwargs.get("before_ts") is None
), f"max_days=0 should map to before_ts=None (no age cap), got {kwargs.get('before_ts')!r}"
# ---------------------------------------------------------------------------
# 7. Lazy loop capture (recorder built before loop is running)
# ---------------------------------------------------------------------------
def test_lazy_loop_capture_without_explicit_loop():
"""Recorder with loop=None still works when record() is called from a running loop."""
async def _run():
# Build the recorder BEFORE passing the loop explicitly — test lazy capture.
recorder, persisted, fired = _make_recorder(loop=None)
# Do NOT call ensure_loop() explicitly — the lazy path in record() must handle it.
recorder.record(
category=ActivityCategory.SYSTEM,
action="lazy.capture",
message="loop captured lazily",
)
assert (
len(persisted) == 1
), "Lazy loop capture failed: entry not persisted when loop=None at construction"
asyncio.run(_run())
def test_lazy_loop_stores_loop_for_subsequent_calls():
"""After the first call from an async context, _loop is populated."""
async def _run():
recorder, persisted, fired = _make_recorder(loop=None)
assert recorder._loop is None
recorder.record(category=ActivityCategory.SYSTEM, action="first", message="m")
# The loop must have been captured.
assert (
recorder._loop is not None
), "recorder._loop was not set after first record() from async context"
assert recorder._loop is asyncio.get_running_loop()
asyncio.run(_run())
# ---------------------------------------------------------------------------
# 8. Module-level singleton accessor
# ---------------------------------------------------------------------------
def test_set_and_get_module_recorder():
"""set_module_recorder / get_module_recorder round-trip."""
original = get_module_recorder()
try:
recorder, _, _ = _make_recorder()
set_module_recorder(recorder)
assert get_module_recorder() is recorder
finally:
# Restore whatever was there before (may be None in test isolation).
import ledgrab.core.activity_log.recorder as _mod
_mod._recorder = original # type: ignore[attr-defined]
def test_get_module_recorder_returns_none_before_set():
"""get_module_recorder() returns None when not yet initialised."""
import ledgrab.core.activity_log.recorder as _mod
original = _mod._recorder # type: ignore[attr-defined]
_mod._recorder = None # type: ignore[attr-defined]
try:
assert get_module_recorder() is None
finally:
_mod._recorder = original # type: ignore[attr-defined]