Files
cleveragents-core/features/steps/audit_wiring_extended_steps.py
T
HAL9000 8ed8750160
CI / push-validation (pull_request) Successful in 23s
CI / helm (pull_request) Successful in 30s
CI / build (pull_request) Successful in 43s
CI / lint (pull_request) Successful in 55s
CI / quality (pull_request) Successful in 54s
CI / typecheck (pull_request) Successful in 57s
CI / security (pull_request) Successful in 1m28s
CI / integration_tests (pull_request) Successful in 3m4s
CI / unit_tests (pull_request) Successful in 7m30s
CI / docker (pull_request) Failing after 14m0s
CI / coverage (pull_request) Failing after 21m7s
CI / status-check (pull_request) Has been cancelled
fix(audit): forward DomainEvent.timestamp to AuditService.record()
AuditService.record() was generating its own timestamp internally,
discarding the original DomainEvent.timestamp. This means audit entries
recorded when an event was audited, not when the domain event actually
occurred, breaking forensic accuracy per §Audit Logging (SEC7).

Changes:
- Add `timestamp: datetime | None = None` keyword parameter to
  AuditService.record(). When provided, uses it as created_at;
  falls back to datetime.now(tz=UTC) for backward compatibility.
  Applied to both the async queue path and the synchronous DB path.
- AuditEventSubscriber._handle_event() now passes timestamp=event.timestamp
  so the original event creation time is preserved in audit entries.
- Add 3 Behave BDD scenarios covering: full pipeline timestamp
  preservation, direct record() with explicit timestamp, and backward
  compatibility (record() without timestamp auto-generates created_at).
- Add preserve_event_timestamp Robot integration test and helper subcommand.
- Add static source check in security_audit.robot verifying the
  timestamp parameter signature exists.

ISSUES CLOSED: #719
2026-05-29 16:36:39 -04:00

298 lines
11 KiB
Python

"""Extended step definitions for AuditService EventBus wiring (Forgejo #581).
Covers additional coverage and security scenarios:
- COV-6: Subscriber recovery after transient failure
- COV-5: Multiple non-security event type filtering
- TFLAW-3: Nested sensitive data redaction
- TFLAW-4: Auto-generated correlation_id propagation
- SEC-1: User identity extraction from details
Split from ``audit_service_wiring_steps.py`` to stay within the
500-line file limit (CONTRIBUTING.md).
"""
from __future__ import annotations
from datetime import UTC, datetime, timedelta
from typing import cast
from behave import given, then, when
from behave.runner import Context
from cleveragents.application.services.audit_event_subscriber import (
AuditEventSubscriber,
)
from cleveragents.application.services.audit_service import AuditService
from cleveragents.infrastructure.events.models import DomainEvent
from cleveragents.infrastructure.events.reactive import ReactiveEventBus
from cleveragents.infrastructure.events.types import EventType
from features.mocks.transient_fail_audit_service import TransientFailAuditService
from features.steps.audit_service_wiring_steps import _fresh_audit_service
__all__: list[str] = []
# ── COV-6: Subscriber recovery after failure ─────────────────────
@given("an event bus with a transiently failing audit service")
def step_event_bus_with_transient_failure(context: Context) -> None:
context.audit_service = _fresh_audit_service()
context.event_bus = ReactiveEventBus()
context.fail_once_service = TransientFailAuditService(context.audit_service)
context.subscriber = AuditEventSubscriber(
audit_service=cast(AuditService, context.fail_once_service),
event_bus=context.event_bus,
)
@when("a plan_applied event is emitted causing a transient failure")
def step_emit_causing_transient_failure(context: Context) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.PLAN_APPLIED,
plan_id="PLAN-TRANSIENT",
details={"action_name": "local/fail-once"},
)
)
@when("a plan_cancelled event is emitted after the transient failure")
def step_emit_after_transient(context: Context) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.PLAN_CANCELLED,
plan_id="PLAN-RECOVER",
details={"reason": "recovery test"},
)
)
@then("the audit log should contain the plan_cancelled entry after recovery")
def step_audit_has_cancelled_after_recovery(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_cancelled")
assert len(entries) >= 1, (
f"Expected plan_cancelled entry after recovery, got {len(entries)}"
)
# ── COV-5: Multiple non-security event type filtering ────────────
@when("non-security events PLAN_CREATED and ACTOR_INVOKED are emitted")
def step_emit_multiple_non_security(context: Context) -> None:
context.event_bus.emit(
DomainEvent(event_type=EventType.PLAN_CREATED, plan_id="P-ns1")
)
context.event_bus.emit(
DomainEvent(event_type=EventType.ACTOR_INVOKED, details={"actor": "test"})
)
@then("the audit log should remain empty")
def step_audit_log_empty(context: Context) -> None:
total = context.audit_service.count()
assert total == 0, f"Expected 0 audit entries, got {total}"
# ── TFLAW-3: Nested sensitive data redaction ─────────────────────
@when("an event with nested sensitive details is emitted")
def step_emit_nested_sensitive(context: Context) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.CONFIG_CHANGED,
details={
"config": {
"api_key": "sk-proj-NESTED1234567890",
"database": {"password": "s3cret!"},
},
"normal_field": "visible",
},
)
)
@then("the nested audit log values should be redacted")
def step_nested_redacted(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="config_changed")
assert len(entries) >= 1, "Expected config_changed entry"
details = entries[0].details
config = details.get("config", {})
assert config.get("api_key") == "***REDACTED***", (
f"Expected nested api_key redacted, got {config.get('api_key')!r}"
)
db = config.get("database", {})
assert db.get("password") == "***REDACTED***", (
f"Expected nested password redacted, got {db.get('password')!r}"
)
assert details.get("normal_field") == "visible"
# ── TFLAW-4: Auto-generated correlation_id propagation ───────────
@when("a plan_applied event without explicit correlation_id is emitted")
def step_emit_auto_correlation(context: Context) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.PLAN_APPLIED,
plan_id="PLAN-AUTO-CORR",
details={"action_name": "local/auto-corr"},
)
)
@then("the audit entry details should contain a non-empty correlation_id")
def step_audit_has_auto_correlation_id(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_applied")
assert len(entries) >= 1, "No plan_applied entries found"
details = entries[0].details
cid = details.get("correlation_id")
assert cid is not None and len(str(cid)) > 0, (
f"Expected non-empty auto-generated correlation_id, got {cid!r}"
)
# ── SEC-1: User identity extraction from details ─────────────────
@when("a session_created event with user_identity in details is emitted")
def step_emit_session_with_user_identity(context: Context) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.SESSION_CREATED,
session_id="SES-UI",
details={
"mode": "interactive",
"user_identity": "test-user@example.com",
},
)
)
@then('the audit entry should have user_identity "{expected_uid}"')
def step_audit_entry_user_identity(context: Context, expected_uid: str) -> None:
entries = context.audit_service.list_entries(event_type="session_created")
assert len(entries) >= 1, "No session_created entries found"
assert entries[0].user_identity == expected_uid, (
f"Expected user_identity={expected_uid!r}, got {entries[0].user_identity!r}"
)
# ── #715: DomainEvent.user_identity field propagation ────────────
@when('a session_created event with user_identity field "{uid}" is emitted')
def step_emit_session_with_user_identity_field(context: Context, uid: str) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.SESSION_CREATED,
session_id="SES-FIELD",
user_identity=uid,
details={"mode": "interactive"},
)
)
@when(
'a session_created event with both user_identity field "{field_uid}" '
'and details identity "{details_uid}" is emitted'
)
def step_emit_session_with_both_identities(
context: Context, field_uid: str, details_uid: str
) -> None:
context.event_bus.emit(
DomainEvent(
event_type=EventType.SESSION_CREATED,
session_id="SES-BOTH",
user_identity=field_uid,
details={
"mode": "interactive",
"user_identity": details_uid,
},
)
)
@then("the audit entry user_identity should be None")
def step_audit_entry_user_identity_none(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_applied")
assert len(entries) >= 1, "No plan_applied entries found"
assert entries[0].user_identity is None, (
f"Expected user_identity=None, got {entries[0].user_identity!r}"
)
# ── #719: DomainEvent.timestamp preservation ─────────────────────
@when("a plan_applied event with a known timestamp is emitted")
def step_emit_plan_applied_with_known_timestamp(context: Context) -> None:
context.known_timestamp = datetime(2024, 6, 15, 10, 30, 0, tzinfo=UTC)
context.event_bus.emit(
DomainEvent(
event_type=EventType.PLAN_APPLIED,
plan_id="PLAN-TS",
timestamp=context.known_timestamp,
)
)
@then("the audit entry created_at should match the event timestamp")
def step_audit_entry_matches_event_timestamp(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_applied")
assert len(entries) >= 1, "No plan_applied entries found"
expected = context.known_timestamp.strftime("%Y-%m-%dT%H:%M:%S.%f")
assert entries[0].created_at == expected, (
f"Expected created_at={expected!r}, got {entries[0].created_at!r}"
)
@given("a direct audit service instance")
def step_direct_audit_service(context: Context) -> None:
context.audit_service = _fresh_audit_service()
@when("record is called with an explicit timestamp")
def step_record_with_explicit_timestamp(context: Context) -> None:
context.explicit_timestamp = datetime(2023, 1, 1, 12, 0, 0, tzinfo=UTC)
context.audit_service.record(
event_type="plan_applied",
plan_id="PLAN-EXPLICIT-TS",
timestamp=context.explicit_timestamp,
)
@then("the audit entry created_at should equal the explicit timestamp")
def step_audit_entry_equals_explicit_timestamp(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_applied")
assert len(entries) >= 1, "No plan_applied entries found"
expected = context.explicit_timestamp.strftime("%Y-%m-%dT%H:%M:%S.%f")
assert entries[0].created_at == expected, (
f"Expected created_at={expected!r}, got {entries[0].created_at!r}"
)
@when("record is called without a timestamp")
def step_record_without_timestamp(context: Context) -> None:
context.before_record = datetime.now(tz=UTC)
context.audit_service.record(
event_type="plan_applied",
plan_id="PLAN-AUTO-TS",
)
context.after_record = datetime.now(tz=UTC)
@then("the audit entry created_at should be close to now")
def step_audit_entry_close_to_now(context: Context) -> None:
entries = context.audit_service.list_entries(event_type="plan_applied")
assert len(entries) >= 1, "No plan_applied entries found"
recorded = datetime.fromisoformat(entries[0].created_at).replace(tzinfo=UTC)
tolerance = timedelta(seconds=60)
lower = context.before_record - tolerance
upper = context.after_record + tolerance
assert lower <= recorded <= upper, (
f"created_at={recorded!r} not within 60s of call time"
)