From b601441da7a75bb5358566ec801df1fcdad47c08 Mon Sep 17 00:00:00 2001 From: Renn F Date: Fri, 8 May 2026 12:18:00 +0200 Subject: [PATCH] fix(audit): record actor's actual role from agents.role at write time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- roboco/services/audit.py | 79 +++++++++++++++++--- tests/unit/services/test_audit.py | 35 +++++++++ tests/unit/services/test_audit_real_query.py | 65 +++++++++++++++- 3 files changed, 169 insertions(+), 10 deletions(-) diff --git a/roboco/services/audit.py b/roboco/services/audit.py index 4707527d..efcdfca9 100644 --- a/roboco/services/audit.py +++ b/roboco/services/audit.py @@ -184,12 +184,19 @@ class AuditService(SingletonService): action: str, reason: str | 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( "Task action denied", event_type=AuditEventType.TASK_ACTION_DENIED.value, agent_id=str(agent_id), - agent_role=agent_role, + agent_role=actual_role, task_id=str(task_id), action=action, reason=reason, @@ -203,7 +210,7 @@ class AuditService(SingletonService): target_id=task_id, severity="warning", details={ - "agent_role": agent_role, + "agent_role": actual_role, "action": action, "reason": reason, }, @@ -214,12 +221,20 @@ class AuditService(SingletonService): self, ctx: StateTransitionDenialContext, ) -> 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( "State transition denied", event_type=AuditEventType.STATE_TRANSITION_DENIED.value, agent_id=str(ctx.agent_id), - agent_role=ctx.agent_role, + agent_role=actual_role, task_id=str(ctx.task_id), current_status=ctx.current_status, target_status=ctx.target_status, @@ -234,7 +249,7 @@ class AuditService(SingletonService): target_id=ctx.task_id, severity="warning", details={ - "agent_role": ctx.agent_role, + "agent_role": actual_role, "current_status": ctx.current_status, "target_status": ctx.target_status, "reason": ctx.reason, @@ -249,12 +264,18 @@ class AuditService(SingletonService): notification_type: str, reason: str | 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( "Notification permission denied", event_type=AuditEventType.NOTIFICATION_DENIED.value, agent_id=str(agent_id), - agent_role=agent_role, + agent_role=actual_role, notification_type=notification_type, reason=reason, timestamp=datetime.now(UTC).isoformat(), @@ -266,7 +287,7 @@ class AuditService(SingletonService): target_type="notification", severity="warning", details={ - "agent_role": agent_role, + "agent_role": actual_role, "notification_type": notification_type, "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: """Resolve an agent slug to its UUID for ``audit_log.agent_id``. diff --git a/tests/unit/services/test_audit.py b/tests/unit/services/test_audit.py index b355b79d..20709b9e 100644 --- a/tests/unit/services/test_audit.py +++ b/tests/unit/services/test_audit.py @@ -191,3 +191,38 @@ def test_get_audit_service_returns_singleton() -> None: a = get_audit_service() b = get_audit_service() 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 diff --git a/tests/unit/services/test_audit_real_query.py b/tests/unit/services/test_audit_real_query.py index 3eafde41..ea0b56fc 100644 --- a/tests/unit/services/test_audit_real_query.py +++ b/tests/unit/services/test_audit_real_query.py @@ -33,10 +33,11 @@ import pytest import pytest_asyncio from roboco.db import base as 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.seeds import initial_data as seeds from roboco.services.audit import AuditService +from sqlalchemy import select from sqlalchemy.ext.asyncio import async_sessionmaker if TYPE_CHECKING: @@ -394,3 +395,65 @@ async def test_resolve_agent_id_by_slug_db_lookup_exception( audit = AuditService() resolved = await audit._resolve_agent_id_by_slug("nope-not-real") 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