Files
temp/features/steps/async_audit_recording_steps.py
T
freemo f0a40afecc refactor(audit): implement async audit recording to unblock event pipeline (#1279)
Implements a write-behind queue with a background daemon thread in AuditService so that record() returns immediately without blocking the calling domain operation on a synchronous SQLite INSERT + COMMIT.

Changes:
- AuditService: add _writer_loop(), _write_payload(), flush() methods and a write-behind queue with a background thread
- record() enqueues the payload and returns a placeholder entry with id=-1 in async mode
- close() calls flush() to drain the queue before closing the session
- Settings: add audit_async (default True) and audit_queue_maxsize (default 10000) fields
- 20 BDD scenarios covering non-blocking record(), flush/close lifecycle, ordering, sync fallback, and settings

Closes #718

Co-authored-by: Jeffrey Phillips Freeman <the@jeffreyfreeman.me>
Co-committed-by: Jeffrey Phillips Freeman <the@jeffreyfreeman.me>
2026-04-02 17:00:53 +00:00

349 lines
13 KiB
Python

"""Step definitions for async audit recording (issue #718).
Tests the write-behind queue, non-blocking record(), flush(), and
graceful shutdown behaviour of :class:`AuditService` in async mode.
Design note: async mode is only active when the service owns its
session (no injected session). Tests therefore create the service
with a ``database_url`` pointing to a temporary SQLite file so that
the background writer thread can open its own connection.
"""
from __future__ import annotations
import tempfile
import time
from behave import given, then, when
from behave.runner import Context
from sqlalchemy import create_engine
from cleveragents.application.services.audit_service import AuditService
from cleveragents.config.settings import Settings
from cleveragents.infrastructure.database.models import Base
__all__: list[str] = []
# ── Helpers ───────────────────────────────────────────────────────
def _make_settings(**overrides: object) -> Settings:
"""Create a fresh Settings instance with optional overrides."""
Settings._instance = None
base = Settings()
if overrides:
return base.model_copy(update=overrides)
return base
def _make_async_service(context: Context) -> AuditService:
"""Create an AuditService in async mode using a temp SQLite file.
The service owns its session so the background writer thread can
open its own connection to the same file.
"""
tmp = tempfile.mktemp(suffix=".db", prefix="audit_async_test_")
context._async_db_path = tmp
db_url = f"sqlite:///{tmp}"
settings = _make_settings(audit_async=True, database_url=db_url)
# Pre-create the table so the background thread doesn't race.
engine = create_engine(db_url, connect_args={"check_same_thread": False})
Base.metadata.create_all(engine, tables=[])
from cleveragents.infrastructure.database.models import AuditLogModel
Base.metadata.create_all(engine, tables=[AuditLogModel.__table__])
engine.dispose()
return AuditService(settings=settings, database_url=db_url)
def _make_sync_service(context: Context) -> AuditService:
"""Create an AuditService in synchronous mode using a temp SQLite file."""
tmp = tempfile.mktemp(suffix=".db", prefix="audit_sync_test_")
context._sync_db_path = tmp
db_url = f"sqlite:///{tmp}"
settings = _make_settings(audit_async=False, database_url=db_url)
from cleveragents.infrastructure.database.models import AuditLogModel
engine = create_engine(db_url)
Base.metadata.create_all(engine, tables=[AuditLogModel.__table__])
engine.dispose()
return AuditService(settings=settings, database_url=db_url)
# ── Given ─────────────────────────────────────────────────────────
@given("an async audit service")
def step_async_audit_service(context: Context) -> None:
context.async_service = _make_async_service(context)
context.async_entry = None
context.async_error = None
context.async_closed = False
@given("an async audit service used as context manager")
def step_async_audit_service_ctx(context: Context) -> None:
context.async_service = _make_async_service(context)
context.async_entry = None
context.async_error = None
context.async_closed = False
context.ctx_entry = None
@given("a synchronous audit service")
def step_sync_audit_service(context: Context) -> None:
context.async_service = _make_sync_service(context)
context.async_entry = None
context.async_error = None
# ── When ──────────────────────────────────────────────────────────
@when('I record a "{event_type}" event in async mode')
def step_record_async(context: Context, event_type: str) -> None:
start = time.monotonic()
context.async_entry = context.async_service.record(event_type=event_type)
context.record_elapsed = time.monotonic() - start
@when('I record {count:d} "{event_type}" events in async mode')
def step_record_multiple_async(context: Context, count: int, event_type: str) -> None:
for i in range(count):
context.async_service.record(
event_type=event_type, plan_id=f"plan-async-{i}"
)
@when("I flush the async audit service")
def step_flush_async(context: Context) -> None:
context.async_error = None
try:
context.async_service.flush()
except Exception as exc:
context.async_error = exc
@when("I flush the async audit service again")
def step_flush_async_again(context: Context) -> None:
try:
context.async_service.flush()
except Exception as exc:
context.async_error = exc
@when("I close the async audit service")
def step_close_async(context: Context) -> None:
context.async_error = None
context.async_closed = True
try:
context.async_service.close()
except Exception as exc:
context.async_error = exc
@when("I close the async audit service again")
def step_close_async_again(context: Context) -> None:
try:
context.async_service.close()
except Exception as exc:
context.async_error = exc
@when('I record a "{event_type}" event synchronously')
def step_record_sync(context: Context, event_type: str) -> None:
context.async_entry = context.async_service.record(event_type=event_type)
@when('I record a "{event_type}" event inside the context manager')
def step_record_inside_ctx(context: Context, event_type: str) -> None:
with context.async_service as svc:
context.ctx_entry = svc.record(event_type=event_type)
context.async_closed = True
@when(
'I record events with plan_ids "{p1}" "{p2}" "{p3}" in async mode'
)
def step_record_ordered_async(
context: Context, p1: str, p2: str, p3: str
) -> None:
for pid in (p1, p2, p3):
context.async_service.record(event_type="plan_applied", plan_id=pid)
context.ordered_plan_ids = [p1, p2, p3]
@when(
'I record an event with invalid type "{event_type}" in async mode'
)
def step_record_invalid_async(context: Context, event_type: str) -> None:
try:
context.async_service.record(event_type=event_type)
context.async_error = None
except ValueError as exc:
context.async_error = exc
# ── Then ──────────────────────────────────────────────────────────
@then("the record call should return immediately")
def step_record_returned_immediately(context: Context) -> None:
# "Immediately" is defined as < 100 ms — a synchronous SQLite write
# typically takes 5-50 ms; the async enqueue should be < 1 ms.
assert context.record_elapsed < 0.1, (
f"record() took {context.record_elapsed:.3f}s — expected < 0.1s"
)
@then('the returned entry should have event_type "{expected}"')
def step_returned_entry_event_type(context: Context, expected: str) -> None:
assert context.async_entry is not None
assert context.async_entry.event_type == expected, (
f"Expected event_type={expected!r}, got {context.async_entry.event_type!r}"
)
@then("the returned entry id should be -1")
def step_returned_entry_id_minus_one(context: Context) -> None:
assert context.async_entry is not None
assert context.async_entry.id == -1, (
f"Expected id=-1 (async placeholder), got {context.async_entry.id}"
)
@then("the returned entry id should be a positive integer")
def step_returned_entry_id_positive(context: Context) -> None:
assert context.async_entry is not None
assert context.async_entry.id > 0, (
f"Expected positive id (sync mode), got {context.async_entry.id}"
)
@then("the audit log should contain {count:d} persisted entry")
@then("the audit log should contain {count:d} persisted entries")
def step_persisted_count(context: Context, count: int) -> None:
actual = context.async_service.count()
assert actual == count, f"Expected {count} persisted entries, got {actual}"
@then("the audit log should contain {count:d} persisted entries after close")
def step_persisted_count_after_close(context: Context, count: int) -> None:
# After close() we need a fresh read session to verify persistence.
db_path = getattr(context, "_async_db_path", None)
if db_path:
from sqlalchemy import create_engine as _ce
from sqlalchemy.orm import sessionmaker as _sm
from cleveragents.infrastructure.database.models import AuditLogModel as _M
engine = _ce(f"sqlite:///{db_path}")
session = _sm(bind=engine)()
actual = session.query(_M).count()
session.close()
engine.dispose()
else:
actual = context.async_service.count()
assert actual == count, (
f"Expected {count} persisted entries after close, got {actual}"
)
@then("the audit log should contain 1 persisted entry after context exit")
def step_persisted_after_ctx_exit(context: Context) -> None:
db_path = getattr(context, "_async_db_path", None)
if db_path:
from sqlalchemy import create_engine as _ce
from sqlalchemy.orm import sessionmaker as _sm
from cleveragents.infrastructure.database.models import AuditLogModel as _M
engine = _ce(f"sqlite:///{db_path}")
session = _sm(bind=engine)()
actual = session.query(_M).count()
session.close()
engine.dispose()
else:
actual = context.async_service.count()
assert actual == 1, (
f"Expected 1 persisted entry after context exit, got {actual}"
)
@then("the audit log should contain 1 persisted entry immediately")
def step_persisted_immediately(context: Context) -> None:
actual = context.async_service.count()
assert actual == 1, (
f"Expected 1 persisted entry immediately (sync mode), got {actual}"
)
@then("the background writer thread should be alive")
def step_writer_thread_alive(context: Context) -> None:
thread = context.async_service._writer_thread
assert thread is not None, "Expected a background writer thread"
assert thread.is_alive(), "Expected background writer thread to be alive"
@then("the background writer thread should be stopped")
def step_writer_thread_stopped(context: Context) -> None:
thread = context.async_service._writer_thread
assert thread is not None, "Expected a background writer thread"
assert not thread.is_alive(), "Expected background writer thread to be stopped"
@then("the entries should be persisted in enqueue order")
def step_entries_in_order(context: Context) -> None:
entries = context.async_service.list_entries(
event_type="plan_applied", limit=100
)
# list_entries returns newest-first; reverse to get enqueue order.
persisted_ids = [e.plan_id for e in reversed(entries)]
assert persisted_ids == context.ordered_plan_ids, (
f"Expected order {context.ordered_plan_ids}, got {persisted_ids}"
)
@then("a ValueError should be raised immediately")
def step_value_error_raised(context: Context) -> None:
assert isinstance(context.async_error, ValueError), (
f"Expected ValueError, got {type(context.async_error)}"
)
@then("no async audit error should be raised")
def step_no_async_audit_error_raised(context: Context) -> None:
assert context.async_error is None, (
f"Expected no error, got {context.async_error}"
)
# ── Settings steps ────────────────────────────────────────────────
@then("audit_async should be True")
def step_audit_async_true(context: Context) -> None:
assert context.settings.audit_async is True, (
f"Expected audit_async=True, got {context.settings.audit_async}"
)
@then("audit_async should be False")
def step_audit_async_false(context: Context) -> None:
assert context.settings.audit_async is False, (
f"Expected audit_async=False, got {context.settings.audit_async}"
)
@then("audit_queue_maxsize should be {expected:d}")
def step_audit_queue_maxsize(context: Context, expected: int) -> None:
assert context.settings.audit_queue_maxsize == expected, (
f"Expected audit_queue_maxsize={expected}, "
f"got {context.settings.audit_queue_maxsize}"
)
# ── Settings Given steps ──────────────────────────────────────────
@given("settings with audit_async False")
def step_settings_audit_async_false(context: Context) -> None:
Settings._instance = None
context.settings = Settings(audit_async=False)