mirror of
https://github.com/rennf93/roboco.git
synced 2026-08-03 07:23:24 +02:00
fix(audit): migrate audit_log.details to JSONB so .astext works
Task 13's has_recent_tracing_gap query used .astext on a generic JSON column, which raises AttributeError at runtime. The choreographer's exception handler swallowed it, leaving the strike-count reset permanently inert in production. Migrate the column to JSONB (which supports .astext + GIN indexing for future audit queries), update the ORM, and add a real-DB integration test that would have caught this.
This commit is contained in:
@@ -0,0 +1,95 @@
|
|||||||
|
"""audit_log.details JSON -> JSONB so .astext works in ORM queries.
|
||||||
|
|
||||||
|
Migration 002 originally created `audit_log.details` as `postgresql.JSONB`
|
||||||
|
when the alembic chain was applied cleanly, BUT the ORM in
|
||||||
|
`roboco/db/tables.py` declared the column as generic `JSON`. Two failure
|
||||||
|
modes followed:
|
||||||
|
|
||||||
|
1. DBs bootstrapped via `Base.metadata.create_all` (the production
|
||||||
|
create_all-fallback path in `roboco.db.base.init_db`, and the test
|
||||||
|
conftest path) created the column as `JSON` — not JSONB. PostgreSQL
|
||||||
|
stores `JSON` as text and exposes a different operator class than
|
||||||
|
`JSONB`, so `details->>'reason'` works at the SQL level but
|
||||||
|
SQLAlchemy's ORM generates the `JSON.Comparator` (no `.astext`)
|
||||||
|
instead of the `JSONB.Comparator` (which has `.astext`).
|
||||||
|
|
||||||
|
2. Even DBs where the alembic-created column IS JSONB at the storage
|
||||||
|
layer still hit the same ORM-side failure, because SQLAlchemy picks
|
||||||
|
the comparator from the column TYPE the ORM declares — not what's on
|
||||||
|
disk.
|
||||||
|
|
||||||
|
`AuditService.has_recent_tracing_gap` filters
|
||||||
|
`details->>'reason' == 'tracing_gap'` for the PM-respawn circuit
|
||||||
|
breaker. With the ORM declaring `JSON`, the `.astext` access raises
|
||||||
|
`AttributeError` at query construction time. The choreographer's
|
||||||
|
exception handler in `_pm_made_rule_following_retry` swallows it and
|
||||||
|
returns False, leaving the strike-count reset (Task 13 887d073)
|
||||||
|
permanently inert.
|
||||||
|
|
||||||
|
This migration converts the column to JSONB at the storage layer
|
||||||
|
(idempotent on already-JSONB DBs because PG accepts a JSONB->JSONB
|
||||||
|
ALTER as a no-op cast). The ORM is updated in the same commit to
|
||||||
|
declare `JSONB`, which is the change that actually unblocks `.astext`.
|
||||||
|
|
||||||
|
Revision ID: 010_audit_log_details_jsonb
|
||||||
|
Revises: 009_enum_reconcile
|
||||||
|
Create Date: 2026-05-03
|
||||||
|
"""
|
||||||
|
|
||||||
|
from __future__ import annotations
|
||||||
|
|
||||||
|
import sqlalchemy as sa
|
||||||
|
from alembic import op
|
||||||
|
from sqlalchemy.dialects import postgresql
|
||||||
|
|
||||||
|
# revision identifiers, used by Alembic.
|
||||||
|
revision = "010_audit_log_details_jsonb"
|
||||||
|
down_revision = "009_enum_reconcile"
|
||||||
|
branch_labels = None
|
||||||
|
depends_on = None
|
||||||
|
|
||||||
|
|
||||||
|
def upgrade() -> None:
|
||||||
|
"""Convert audit_log.details from JSON to JSONB.
|
||||||
|
|
||||||
|
PG can convert JSON -> JSONB in place because they're text-compatible.
|
||||||
|
`USING details::jsonb` re-parses every existing row as JSONB. The
|
||||||
|
server_default is updated from `'{}'::json` to `'{}'::jsonb` to match
|
||||||
|
the new column type — leaving it as `'{}'::json` would cause an
|
||||||
|
implicit cast on every INSERT.
|
||||||
|
|
||||||
|
Idempotent on a database where the column is already JSONB: the
|
||||||
|
`details::jsonb` cast on a JSONB value is a no-op, the type change
|
||||||
|
is a no-op, and the default is reset to the same value.
|
||||||
|
"""
|
||||||
|
op.alter_column(
|
||||||
|
"audit_log",
|
||||||
|
"details",
|
||||||
|
existing_type=sa.JSON(),
|
||||||
|
type_=postgresql.JSONB(),
|
||||||
|
existing_nullable=False,
|
||||||
|
existing_server_default=sa.text("'{}'::json"),
|
||||||
|
server_default=sa.text("'{}'::jsonb"),
|
||||||
|
postgresql_using="details::jsonb",
|
||||||
|
)
|
||||||
|
|
||||||
|
|
||||||
|
def downgrade() -> None:
|
||||||
|
"""Convert audit_log.details back from JSONB to JSON.
|
||||||
|
|
||||||
|
JSONB -> JSON is also a safe cast (JSONB serializes back to text).
|
||||||
|
The default is reset to the original `'{}'::json` shape. Note: the
|
||||||
|
ORM-side `JSONB` declaration must be reverted alongside this
|
||||||
|
downgrade, or `.astext` queries will start raising AttributeError
|
||||||
|
again at runtime.
|
||||||
|
"""
|
||||||
|
op.alter_column(
|
||||||
|
"audit_log",
|
||||||
|
"details",
|
||||||
|
existing_type=postgresql.JSONB(),
|
||||||
|
type_=sa.JSON(),
|
||||||
|
existing_nullable=False,
|
||||||
|
existing_server_default=sa.text("'{}'::jsonb"),
|
||||||
|
server_default=sa.text("'{}'::json"),
|
||||||
|
postgresql_using="details::json",
|
||||||
|
)
|
||||||
+7
-2
@@ -23,7 +23,7 @@ from sqlalchemy import (
|
|||||||
Text,
|
Text,
|
||||||
UniqueConstraint,
|
UniqueConstraint,
|
||||||
)
|
)
|
||||||
from sqlalchemy.dialects.postgresql import ARRAY, UUID
|
from sqlalchemy.dialects.postgresql import ARRAY, JSONB, UUID
|
||||||
from sqlalchemy.orm import Mapped, mapped_column, relationship
|
from sqlalchemy.orm import Mapped, mapped_column, relationship
|
||||||
|
|
||||||
from roboco.db.base import Base
|
from roboco.db.base import Base
|
||||||
@@ -1552,7 +1552,12 @@ class AuditLogTable(Base):
|
|||||||
target_type: Mapped[str | None] = mapped_column(String(40), nullable=True)
|
target_type: Mapped[str | None] = mapped_column(String(40), nullable=True)
|
||||||
target_id: Mapped[UUID | None] = mapped_column(UUID(as_uuid=True), nullable=True)
|
target_id: Mapped[UUID | None] = mapped_column(UUID(as_uuid=True), nullable=True)
|
||||||
severity: Mapped[str] = mapped_column(String(16), nullable=False, default="info")
|
severity: Mapped[str] = mapped_column(String(16), nullable=False, default="info")
|
||||||
details: Mapped[dict[str, Any]] = mapped_column(JSON, default=dict, nullable=False)
|
# JSONB (not generic JSON) so the comparator exposes `.astext` —
|
||||||
|
# `AuditService.has_recent_tracing_gap` filters
|
||||||
|
# `details->>'reason' == 'tracing_gap'`, which the generic JSON Comparator
|
||||||
|
# doesn't support (raises AttributeError). JSONB also supports GIN
|
||||||
|
# indexing for future audit queries.
|
||||||
|
details: Mapped[dict[str, Any]] = mapped_column(JSONB, default=dict, nullable=False)
|
||||||
timestamp: Mapped[datetime] = mapped_column(
|
timestamp: Mapped[datetime] = mapped_column(
|
||||||
DateTime(timezone=True),
|
DateTime(timezone=True),
|
||||||
default=lambda: datetime.now(UTC),
|
default=lambda: datetime.now(UTC),
|
||||||
|
|||||||
@@ -0,0 +1,209 @@
|
|||||||
|
"""Real-DB integration test for ``AuditService.has_recent_tracing_gap``.
|
||||||
|
|
||||||
|
Why this test exists
|
||||||
|
--------------------
|
||||||
|
Task 13 (commit 887d073) added the PM-respawn rule-following retry
|
||||||
|
detection. The query at ``roboco/services/audit.py:489`` filters
|
||||||
|
``details->>'reason' == 'tracing_gap'`` via SQLAlchemy's ``.astext``
|
||||||
|
accessor — but ``.astext`` only exists on ``JSONB.Comparator``, NOT on
|
||||||
|
the generic ``JSON.Comparator``. The ORM declared the column as ``JSON``,
|
||||||
|
so the access raised ``AttributeError`` at query construction time and
|
||||||
|
the choreographer's exception handler swallowed it.
|
||||||
|
|
||||||
|
The six existing unit tests in
|
||||||
|
``tests/unit/runtime/test_pm_respawn_reset.py`` all mocked
|
||||||
|
``audit.has_recent_tracing_gap`` directly, never exercising the SQL —
|
||||||
|
that's why they passed despite the production code being inert.
|
||||||
|
|
||||||
|
This test issues the real query against a real Postgres backend (the
|
||||||
|
session-scoped test DB from ``tests/conftest.py``). It seeds an audit
|
||||||
|
row with the production shape and asserts the True / False outcomes.
|
||||||
|
With the ORM correctly declaring ``JSONB``, this passes; with the prior
|
||||||
|
``JSON`` declaration it would raise the same ``AttributeError`` the
|
||||||
|
production code raises.
|
||||||
|
"""
|
||||||
|
|
||||||
|
from __future__ import annotations
|
||||||
|
|
||||||
|
from datetime import UTC, datetime, timedelta
|
||||||
|
from typing import TYPE_CHECKING
|
||||||
|
from uuid import UUID, uuid4
|
||||||
|
|
||||||
|
import pytest
|
||||||
|
import pytest_asyncio
|
||||||
|
from roboco.db import base as roboco_db_base
|
||||||
|
from roboco.db.tables import AgentTable
|
||||||
|
from roboco.models.base import AgentRole, AgentStatus
|
||||||
|
from roboco.services.audit import AuditService
|
||||||
|
from sqlalchemy.ext.asyncio import async_sessionmaker
|
||||||
|
|
||||||
|
if TYPE_CHECKING:
|
||||||
|
from collections.abc import AsyncIterator
|
||||||
|
|
||||||
|
from sqlalchemy.ext.asyncio import AsyncSession
|
||||||
|
|
||||||
|
|
||||||
|
async def _seed_agent(session: AsyncSession) -> UUID:
|
||||||
|
"""Insert one minimal AgentTable row and return its id.
|
||||||
|
|
||||||
|
``audit_log.agent_id`` has a SET NULL FK to ``agents.id``. Without an
|
||||||
|
actual agent row the persist silently fails (best-effort) and the
|
||||||
|
test would assert against zero rows for the wrong reason.
|
||||||
|
"""
|
||||||
|
agent = AgentTable(
|
||||||
|
id=uuid4(),
|
||||||
|
name="Audit Test Agent",
|
||||||
|
slug=f"audit-test-{uuid4().hex[:8]}",
|
||||||
|
role=AgentRole.CELL_PM,
|
||||||
|
team=None,
|
||||||
|
status=AgentStatus.ACTIVE,
|
||||||
|
model_config={},
|
||||||
|
system_prompt="audit test",
|
||||||
|
capabilities=[],
|
||||||
|
permissions={},
|
||||||
|
metrics={},
|
||||||
|
)
|
||||||
|
session.add(agent)
|
||||||
|
await session.commit()
|
||||||
|
return UUID(str(agent.id))
|
||||||
|
|
||||||
|
|
||||||
|
@pytest_asyncio.fixture
|
||||||
|
async def patched_session_factory(
|
||||||
|
db_session: AsyncSession, monkeypatch: pytest.MonkeyPatch
|
||||||
|
) -> AsyncIterator[AsyncSession]:
|
||||||
|
"""Point ``get_session_factory`` at the test-DB engine for the run.
|
||||||
|
|
||||||
|
``AuditService.log_event`` and ``has_recent_tracing_gap`` both open
|
||||||
|
their own sessions via ``roboco.db.base.get_session_factory()`` —
|
||||||
|
which without intervention binds to the production database URL
|
||||||
|
from ``settings``. We hijack the factory to bind to the same engine
|
||||||
|
the test fixture is using so the inserts and SELECT see the same
|
||||||
|
rows.
|
||||||
|
|
||||||
|
Yields ``db_session`` so callers can also seed FK targets directly.
|
||||||
|
"""
|
||||||
|
test_engine = db_session.bind
|
||||||
|
test_factory = async_sessionmaker(
|
||||||
|
bind=test_engine, expire_on_commit=False, autoflush=False
|
||||||
|
)
|
||||||
|
monkeypatch.setattr(roboco_db_base, "get_session_factory", lambda: test_factory)
|
||||||
|
yield db_session
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_has_recent_tracing_gap_finds_seeded_row(
|
||||||
|
patched_session_factory: AsyncSession,
|
||||||
|
) -> None:
|
||||||
|
"""A seeded gateway.rejected row with reason=tracing_gap is detected.
|
||||||
|
|
||||||
|
Exercises the real SQL path including ``details->>'reason'``. With
|
||||||
|
the ORM declaring ``JSON`` (the bug), this raises AttributeError at
|
||||||
|
query construction. With ``JSONB`` (the fix), it executes and
|
||||||
|
returns True.
|
||||||
|
"""
|
||||||
|
agent_id = await _seed_agent(patched_session_factory)
|
||||||
|
audit = AuditService()
|
||||||
|
task_id = uuid4()
|
||||||
|
since = datetime.now(UTC) - timedelta(seconds=60)
|
||||||
|
|
||||||
|
await audit.log_event(
|
||||||
|
event_type="gateway.rejected",
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
details={"verb": "delegate", "reason": "tracing_gap", "missing": ["plan"]},
|
||||||
|
)
|
||||||
|
|
||||||
|
result = await audit.has_recent_tracing_gap(
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
since=since,
|
||||||
|
)
|
||||||
|
assert result is True
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_has_recent_tracing_gap_returns_false_for_other_task(
|
||||||
|
patched_session_factory: AsyncSession,
|
||||||
|
) -> None:
|
||||||
|
"""Same agent, different task id — must NOT match."""
|
||||||
|
agent_id = await _seed_agent(patched_session_factory)
|
||||||
|
audit = AuditService()
|
||||||
|
seeded_task_id = uuid4()
|
||||||
|
other_task_id = uuid4()
|
||||||
|
since = datetime.now(UTC) - timedelta(seconds=60)
|
||||||
|
|
||||||
|
await audit.log_event(
|
||||||
|
event_type="gateway.rejected",
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=seeded_task_id,
|
||||||
|
details={"reason": "tracing_gap"},
|
||||||
|
)
|
||||||
|
|
||||||
|
result = await audit.has_recent_tracing_gap(
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=other_task_id,
|
||||||
|
since=since,
|
||||||
|
)
|
||||||
|
assert result is False
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_has_recent_tracing_gap_returns_false_for_other_reason(
|
||||||
|
patched_session_factory: AsyncSession,
|
||||||
|
) -> None:
|
||||||
|
"""Reason other than 'tracing_gap' on the same (agent, task) — no match.
|
||||||
|
|
||||||
|
This is the most critical assertion: it proves the JSONB
|
||||||
|
``details->>'reason' == 'tracing_gap'`` predicate is actually
|
||||||
|
evaluated by Postgres, not silently dropped because ``.astext``
|
||||||
|
raised before the SQL was ever issued.
|
||||||
|
"""
|
||||||
|
agent_id = await _seed_agent(patched_session_factory)
|
||||||
|
audit = AuditService()
|
||||||
|
task_id = uuid4()
|
||||||
|
since = datetime.now(UTC) - timedelta(seconds=60)
|
||||||
|
|
||||||
|
await audit.log_event(
|
||||||
|
event_type="gateway.rejected",
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
details={"reason": "permission_denied"},
|
||||||
|
)
|
||||||
|
|
||||||
|
result = await audit.has_recent_tracing_gap(
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
since=since,
|
||||||
|
)
|
||||||
|
assert result is False
|
||||||
|
|
||||||
|
|
||||||
|
@pytest.mark.asyncio
|
||||||
|
async def test_has_recent_tracing_gap_respects_since_window(
|
||||||
|
patched_session_factory: AsyncSession,
|
||||||
|
) -> None:
|
||||||
|
"""Rows older than ``since`` must not match.
|
||||||
|
|
||||||
|
``log_event`` always stamps `timestamp = now()`. We pass a `since`
|
||||||
|
one hour in the future to force every existing row to fall outside
|
||||||
|
the window.
|
||||||
|
"""
|
||||||
|
agent_id = await _seed_agent(patched_session_factory)
|
||||||
|
audit = AuditService()
|
||||||
|
task_id = uuid4()
|
||||||
|
future_since = datetime.now(UTC) + timedelta(hours=1)
|
||||||
|
|
||||||
|
await audit.log_event(
|
||||||
|
event_type="gateway.rejected",
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
details={"reason": "tracing_gap"},
|
||||||
|
)
|
||||||
|
|
||||||
|
result = await audit.has_recent_tracing_gap(
|
||||||
|
agent_id=agent_id,
|
||||||
|
task_id=task_id,
|
||||||
|
since=future_since,
|
||||||
|
)
|
||||||
|
assert result is False
|
||||||
Reference in New Issue
Block a user