fix(audit): record actor's actual role from agents.role at write time

The 2026-05-08 trace caught an audit row with actor=main-pm but
agent_role=cell_pm — the caller had supplied the verb's *expected*
role rather than the actor's actual role. Forensics work that joined
audit_log on agent_role would silently miscategorize the row.

Fix: AuditService now reads the actor's role directly from
agents.role at write time via the new _resolve_actor_role_from_db
helper. Wired into log_task_action_denial,
log_state_transition_denial, and log_notification_denial. The
caller-supplied role param is kept as a best-effort fallback for the
case where the DB lookup fails (singleton-without-DB paths,
permission errors, etc.) so audit writes never block the operation
being audited.

Coverage:
  - 3 unit tests (test_audit.py) for the no-DB / invalid-id paths
  - 1 unit-with-real-DB test (test_audit_real_query.py) verifying
    the persisted row's agent_role is read from DB even when the
    caller passes a deliberately-wrong role
  - 1 unit-with-real-DB test for the no-row case

Tests: 3135 passing, 100% coverage, ruff clean.
This commit is contained in:
Renn F
2026-05-08 12:18:00 +02:00
parent 19f27b4f88
commit b601441da7
3 changed files with 169 additions and 10 deletions
+70 -9
View File
@@ -184,12 +184,19 @@ class AuditService(SingletonService):
action: str, action: str,
reason: str | None = None, reason: str | None = None,
) -> None: ) -> None:
"""Log a task action denial.""" """Log a task action denial.
The persisted ``agent_role`` is the actor's actual role read from
``agents.role`` at write time, not the caller-supplied param.
Pre-fix the supplied param could disagree with the DB (verb's
expected role vs caller's actual role); the DB is authoritative.
"""
actual_role = await self._resolve_actor_role_from_db(agent_id) or agent_role
self.log.warning( self.log.warning(
"Task action denied", "Task action denied",
event_type=AuditEventType.TASK_ACTION_DENIED.value, event_type=AuditEventType.TASK_ACTION_DENIED.value,
agent_id=str(agent_id), agent_id=str(agent_id),
agent_role=agent_role, agent_role=actual_role,
task_id=str(task_id), task_id=str(task_id),
action=action, action=action,
reason=reason, reason=reason,
@@ -203,7 +210,7 @@ class AuditService(SingletonService):
target_id=task_id, target_id=task_id,
severity="warning", severity="warning",
details={ details={
"agent_role": agent_role, "agent_role": actual_role,
"action": action, "action": action,
"reason": reason, "reason": reason,
}, },
@@ -214,12 +221,20 @@ class AuditService(SingletonService):
self, self,
ctx: StateTransitionDenialContext, ctx: StateTransitionDenialContext,
) -> None: ) -> None:
"""Log a state transition denial.""" """Log a state transition denial.
See log_task_action_denial: the persisted role is the actor's
actual role read from agents.role at write time, falling back
to ctx.agent_role only when the DB lookup fails.
"""
actual_role = (
await self._resolve_actor_role_from_db(ctx.agent_id) or ctx.agent_role
)
self.log.warning( self.log.warning(
"State transition denied", "State transition denied",
event_type=AuditEventType.STATE_TRANSITION_DENIED.value, event_type=AuditEventType.STATE_TRANSITION_DENIED.value,
agent_id=str(ctx.agent_id), agent_id=str(ctx.agent_id),
agent_role=ctx.agent_role, agent_role=actual_role,
task_id=str(ctx.task_id), task_id=str(ctx.task_id),
current_status=ctx.current_status, current_status=ctx.current_status,
target_status=ctx.target_status, target_status=ctx.target_status,
@@ -234,7 +249,7 @@ class AuditService(SingletonService):
target_id=ctx.task_id, target_id=ctx.task_id,
severity="warning", severity="warning",
details={ details={
"agent_role": ctx.agent_role, "agent_role": actual_role,
"current_status": ctx.current_status, "current_status": ctx.current_status,
"target_status": ctx.target_status, "target_status": ctx.target_status,
"reason": ctx.reason, "reason": ctx.reason,
@@ -249,12 +264,18 @@ class AuditService(SingletonService):
notification_type: str, notification_type: str,
reason: str | None = None, reason: str | None = None,
) -> None: ) -> None:
"""Log a notification permission denial.""" """Log a notification permission denial.
See log_task_action_denial: the persisted role is the actor's
actual role read from agents.role at write time, falling back
to the supplied param only when the DB lookup fails.
"""
actual_role = await self._resolve_actor_role_from_db(agent_id) or agent_role
self.log.warning( self.log.warning(
"Notification permission denied", "Notification permission denied",
event_type=AuditEventType.NOTIFICATION_DENIED.value, event_type=AuditEventType.NOTIFICATION_DENIED.value,
agent_id=str(agent_id), agent_id=str(agent_id),
agent_role=agent_role, agent_role=actual_role,
notification_type=notification_type, notification_type=notification_type,
reason=reason, reason=reason,
timestamp=datetime.now(UTC).isoformat(), timestamp=datetime.now(UTC).isoformat(),
@@ -266,7 +287,7 @@ class AuditService(SingletonService):
target_type="notification", target_type="notification",
severity="warning", severity="warning",
details={ details={
"agent_role": agent_role, "agent_role": actual_role,
"notification_type": notification_type, "notification_type": notification_type,
"reason": reason, "reason": reason,
}, },
@@ -446,6 +467,46 @@ class AuditService(SingletonService):
) )
) )
async def _resolve_actor_role_from_db(
self, agent_id: str | UUID | None
) -> str | None:
"""Read the actor's actual role from agents.role at write time.
Pre-2026-05-08, every denial-log call took an `agent_role` string
from the caller. The trace caught a row where actor=main-pm but
agent_role=cell_pm — caller had passed the verb's *expected*
role rather than the actor's actual role. This helper looks up
the truth at write time. Best-effort: returns None on any
failure so the caller's supplied role can be used as a fallback.
"""
actor_uuid = _coerce_uuid(agent_id)
if actor_uuid is None:
return None
try:
from sqlalchemy import select
from roboco.db.base import get_session_factory
from roboco.db.tables import AgentTable
session_factory = get_session_factory()
async with session_factory() as db:
result = await db.execute(
select(AgentTable.role).where(AgentTable.id == actor_uuid)
)
value = result.scalar_one_or_none()
if value is None:
return None
# AgentTable.role is an enum; .value gives the canonical string
# (e.g. "main_pm"). Defensive: handle plain str too.
return getattr(value, "value", None) or str(value)
except Exception as e:
self.log.debug(
"DB actor-role lookup failed for audit row",
agent_id=str(agent_id),
error=str(e),
)
return None
async def _resolve_agent_id_by_slug(self, agent_slug: str) -> UUID | None: async def _resolve_agent_id_by_slug(self, agent_slug: str) -> UUID | None:
"""Resolve an agent slug to its UUID for ``audit_log.agent_id``. """Resolve an agent slug to its UUID for ``audit_log.agent_id``.
+35
View File
@@ -191,3 +191,38 @@ def test_get_audit_service_returns_singleton() -> None:
a = get_audit_service() a = get_audit_service()
b = get_audit_service() b = get_audit_service()
assert a is b assert a is b
# ---------------------------------------------------------------------------
# _resolve_actor_role_from_db — Task 7 of the gateway introspection plan.
# Pre-fix, denial-log calls trusted the caller-supplied agent_role string.
# The 2026-05-08 trace caught actor=main-pm with agent_role=cell_pm because
# the supplied role was the verb's expected role, not the actor's actual
# role. Fix: read agents.role at write time, fall back to the supplied
# string only when the DB lookup fails.
# ---------------------------------------------------------------------------
@pytest.mark.asyncio
async def test_resolve_actor_role_returns_none_for_none(svc: AuditService) -> None:
assert await svc._resolve_actor_role_from_db(None) is None
@pytest.mark.asyncio
async def test_resolve_actor_role_returns_none_for_invalid_uuid(
svc: AuditService,
) -> None:
"""A slug or malformed UUID coerces to None and short-circuits."""
assert await svc._resolve_actor_role_from_db("be-dev-1") is None
@pytest.mark.asyncio
async def test_resolve_actor_role_returns_none_when_db_unavailable(
svc: AuditService,
) -> None:
"""No DB session factory configured -> best-effort returns None."""
# `get_session_factory()` will raise without a configured engine.
# The helper catches the error and returns None so audit writes
# still proceed with the caller-supplied role as fallback.
result = await svc._resolve_actor_role_from_db(uuid4())
assert result is None
+64 -1
View File
@@ -33,10 +33,11 @@ import pytest
import pytest_asyncio import pytest_asyncio
from roboco.db import base as db_base from roboco.db import base as db_base
from roboco.db import base as roboco_db_base from roboco.db import base as roboco_db_base
from roboco.db.tables import AgentTable from roboco.db.tables import AgentTable, AuditLogTable
from roboco.models.base import AgentRole, AgentStatus from roboco.models.base import AgentRole, AgentStatus
from roboco.seeds import initial_data as seeds from roboco.seeds import initial_data as seeds
from roboco.services.audit import AuditService from roboco.services.audit import AuditService
from sqlalchemy import select
from sqlalchemy.ext.asyncio import async_sessionmaker from sqlalchemy.ext.asyncio import async_sessionmaker
if TYPE_CHECKING: if TYPE_CHECKING:
@@ -394,3 +395,65 @@ async def test_resolve_agent_id_by_slug_db_lookup_exception(
audit = AuditService() audit = AuditService()
resolved = await audit._resolve_agent_id_by_slug("nope-not-real") resolved = await audit._resolve_agent_id_by_slug("nope-not-real")
assert resolved is None assert resolved is None
@pytest.mark.asyncio
async def test_log_task_action_denial_records_actual_db_role(
patched_session_factory: AsyncSession,
) -> None:
"""Task 7: audit row's agent_role comes from agents.role, not the param.
Pre-fix the caller-supplied agent_role landed in the persisted row
verbatim. The 2026-05-08 trace caught actor=main-pm with
agent_role=cell_pm because the verb's expected role had been
supplied. Post-fix the writer reads agents.role at write time and
uses that as the source of truth.
"""
# Seed agent with role=CELL_PM. We then call the denial logger with
# a deliberately-wrong agent_role param ("main_pm") and verify the
# persisted row reflects the DB role, not the param.
agent_id = await _seed_agent(patched_session_factory)
audit = AuditService()
task_id = uuid4()
await audit.log_task_action_denial(
agent_id=agent_id,
agent_role="main_pm", # WRONG on purpose
task_id=task_id,
action="delegate",
reason="state mismatch",
)
rows = (
(
await patched_session_factory.execute(
select(AuditLogTable).where(AuditLogTable.agent_id == agent_id)
)
)
.scalars()
.all()
)
assert len(rows) == 1, f"expected exactly 1 audit row, got {len(rows)}"
assert rows[0].details["agent_role"] == "cell_pm", (
f"expected DB role 'cell_pm', got "
f"{rows[0].details['agent_role']!r} — Task 7 fix is broken"
)
@pytest.mark.asyncio
async def test_resolve_actor_role_returns_none_when_agent_not_found(
patched_session_factory: AsyncSession,
) -> None:
"""DB session works but no row matches the agent_id -> returns None.
`patched_session_factory` is required for its side effect: it
monkeypatches `roboco.db.base.get_session_factory` to bind to the
test DB. Without it, the helper would hit the no-DB path instead
of the no-row path we want to cover.
"""
assert patched_session_factory is not None # fixture used for monkeypatch
audit = AuditService()
# Random UUID with no seeded agent — query returns scalar_one_or_none()
# = None, which the helper translates to None.
result = await audit._resolve_actor_role_from_db(uuid4())
assert result is None