diff --git a/alembic/versions/0046_add_generation_tool_log.py b/alembic/versions/0046_add_generation_tool_log.py new file mode 100644 index 0000000..32ff4cf --- /dev/null +++ b/alembic/versions/0046_add_generation_tool_log.py @@ -0,0 +1,103 @@ +"""generation_tool_log: per-turn tool-call telemetry + +Revision ID: 0046 +Revises: 0045 +Create Date: 2026-05-21 + +Captures one row per assistant turn, recording which tools the model +could have used, which it attempted, which fired successfully, and +which failed (with error details). The empirical surface for +evaluating model swaps and answering "does model X actually fire +record_moment when it should?" without relying on anecdote. +""" +from alembic import op +import sqlalchemy as sa +from sqlalchemy.dialects.postgresql import ARRAY, JSONB + + +revision = "0046" +down_revision = "0045" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.create_table( + "generation_tool_log", + sa.Column("id", sa.Integer, primary_key=True), + sa.Column( + "user_id", + sa.Integer, + sa.ForeignKey("users.id", ondelete="CASCADE"), + nullable=False, + ), + sa.Column( + "conv_id", + sa.Integer, + sa.ForeignKey("conversations.id", ondelete="CASCADE"), + nullable=False, + ), + # SET NULL (not CASCADE) so the telemetry row survives if the + # underlying assistant message is later deleted — we want to keep + # the per-turn outcome record for retrospective analysis. + sa.Column( + "assistant_message_id", + sa.Integer, + sa.ForeignKey("messages.id", ondelete="SET NULL"), + nullable=True, + ), + sa.Column("model", sa.Text, nullable=False), + sa.Column("think_enabled", sa.Boolean, nullable=False), + sa.Column( + "tools_available", + ARRAY(sa.Text), + nullable=False, + server_default=sa.text("'{}'::text[]"), + ), + sa.Column( + "tools_attempted", + ARRAY(sa.Text), + nullable=False, + server_default=sa.text("'{}'::text[]"), + ), + sa.Column( + "tools_succeeded", + ARRAY(sa.Text), + nullable=False, + server_default=sa.text("'{}'::text[]"), + ), + # JSONB array of {name, error} objects so failed-tool details are + # queryable without a separate failure table. + sa.Column( + "tools_failed", + JSONB, + nullable=False, + server_default=sa.text("'[]'::jsonb"), + ), + sa.Column( + "created_at", + sa.DateTime(timezone=True), + nullable=False, + server_default=sa.text("now()"), + ), + ) + # Common query: "recent tool outcomes for this user, filterable by model." + op.create_index( + "ix_generation_tool_log_user_created", + "generation_tool_log", + ["user_id", sa.text("created_at DESC")], + ) + # Per-conversation lookup for the journal page's own retrospection. + op.create_index( + "ix_generation_tool_log_conv", + "generation_tool_log", + ["conv_id"], + ) + + +def downgrade() -> None: + op.drop_index("ix_generation_tool_log_conv", table_name="generation_tool_log") + op.drop_index( + "ix_generation_tool_log_user_created", table_name="generation_tool_log" + ) + op.drop_table("generation_tool_log") diff --git a/src/fabledassistant/models/__init__.py b/src/fabledassistant/models/__init__.py index a8b9c71..37c4af2 100644 --- a/src/fabledassistant/models/__init__.py +++ b/src/fabledassistant/models/__init__.py @@ -49,3 +49,4 @@ from fabledassistant.models.moment import ( # noqa: E402, F401 moment_tasks, moment_notes, ) +from fabledassistant.models.generation_tool_log import GenerationToolLog # noqa: E402, F401 diff --git a/src/fabledassistant/models/generation_tool_log.py b/src/fabledassistant/models/generation_tool_log.py new file mode 100644 index 0000000..1322143 --- /dev/null +++ b/src/fabledassistant/models/generation_tool_log.py @@ -0,0 +1,75 @@ +from datetime import datetime, timezone + +from sqlalchemy import Boolean, DateTime, ForeignKey, Index, Integer, Text +from sqlalchemy.dialects.postgresql import ARRAY, JSONB +from sqlalchemy.orm import Mapped, mapped_column + +from fabledassistant.models import Base + + +class GenerationToolLog(Base): + """One row per assistant turn — what tools the model could/did use. + + Lets the operator answer "does model X actually fire record_moment?" + empirically across model swaps without relying on anecdote. + """ + + __tablename__ = "generation_tool_log" + + id: Mapped[int] = mapped_column(primary_key=True) + user_id: Mapped[int] = mapped_column( + Integer, + ForeignKey("users.id", ondelete="CASCADE"), + nullable=False, + ) + conv_id: Mapped[int] = mapped_column( + Integer, + ForeignKey("conversations.id", ondelete="CASCADE"), + nullable=False, + ) + # SET NULL (migration matches) so the telemetry row survives if the + # underlying assistant message is later deleted. + assistant_message_id: Mapped[int | None] = mapped_column( + Integer, + ForeignKey("messages.id", ondelete="SET NULL"), + nullable=True, + ) + model: Mapped[str] = mapped_column(Text, nullable=False) + think_enabled: Mapped[bool] = mapped_column(Boolean, nullable=False) + tools_available: Mapped[list[str]] = mapped_column( + ARRAY(Text), nullable=False, default=list + ) + tools_attempted: Mapped[list[str]] = mapped_column( + ARRAY(Text), nullable=False, default=list + ) + tools_succeeded: Mapped[list[str]] = mapped_column( + ARRAY(Text), nullable=False, default=list + ) + # JSONB list of {name, error} dicts. + tools_failed: Mapped[list[dict]] = mapped_column( + JSONB, nullable=False, default=list + ) + created_at: Mapped[datetime] = mapped_column( + DateTime(timezone=True), + default=lambda: datetime.now(timezone.utc), + ) + + __table_args__ = ( + Index("ix_generation_tool_log_user_created", "user_id", created_at.desc()), + Index("ix_generation_tool_log_conv", "conv_id"), + ) + + def to_dict(self) -> dict: + return { + "id": self.id, + "user_id": self.user_id, + "conv_id": self.conv_id, + "assistant_message_id": self.assistant_message_id, + "model": self.model, + "think_enabled": self.think_enabled, + "tools_available": list(self.tools_available or []), + "tools_attempted": list(self.tools_attempted or []), + "tools_succeeded": list(self.tools_succeeded or []), + "tools_failed": list(self.tools_failed or []), + "created_at": self.created_at.isoformat() if self.created_at else None, + } diff --git a/src/fabledassistant/services/generation_log.py b/src/fabledassistant/services/generation_log.py new file mode 100644 index 0000000..4264766 --- /dev/null +++ b/src/fabledassistant/services/generation_log.py @@ -0,0 +1,111 @@ +"""Per-turn tool-call telemetry for assistant generations. + +Captures the empirical surface for evaluating model swaps: +- Which tools were available to the model on this turn? +- Which did it attempt to call? +- Which succeeded? +- Which failed, and with what error? + +One row per assistant turn. Designed to answer questions like +"does mistral-small actually fire record_moment when it should?" +without relying on anecdote across model changes. +""" +from __future__ import annotations + +import logging +from typing import Iterable + +from sqlalchemy import select + +from fabledassistant.models import async_session +from fabledassistant.models.generation_tool_log import GenerationToolLog + +logger = logging.getLogger(__name__) + + +async def log_tool_outcomes( + *, + user_id: int, + conv_id: int, + assistant_message_id: int | None, + model: str, + think_enabled: bool, + tools_available: Iterable[str], + tool_calls: Iterable[dict], +) -> None: + """Persist one row capturing this turn's tool-call outcomes. + + `tool_calls` is the assembled `all_tool_calls` list from + `generation_task.run_generation`. Each entry has the shape: + {"function": , "arguments": ..., "result": ..., "status": ...} + where `status` is "success" or "error" and `result` may contain an + `error` field when status is "error". + + Fire-and-forget from the caller's perspective — failure here must not + affect the user-facing generation flow, so exceptions are caught and + logged rather than propagated. + """ + try: + available = sorted({str(t) for t in tools_available if t}) + attempted: list[str] = [] + succeeded: list[str] = [] + failed: list[dict] = [] + for call in tool_calls: + name = str(call.get("function") or call.get("name") or "").strip() + if not name: + continue + attempted.append(name) + status = call.get("status") + result = call.get("result") or {} + err = result.get("error") if isinstance(result, dict) else None + is_error = (status == "error") or bool(err) or ( + isinstance(result, dict) and result.get("success") is False + ) + if is_error: + failed.append({"name": name, "error": str(err or "unspecified")[:500]}) + else: + succeeded.append(name) + + async with async_session() as session: + session.add( + GenerationToolLog( + user_id=user_id, + conv_id=conv_id, + assistant_message_id=assistant_message_id, + model=model, + think_enabled=think_enabled, + tools_available=available, + tools_attempted=attempted, + tools_succeeded=succeeded, + tools_failed=failed, + ) + ) + await session.commit() + except Exception: + logger.warning( + "Failed to persist generation_tool_log for conv %d (msg=%s, model=%s)", + conv_id, + assistant_message_id, + model, + exc_info=True, + ) + + +async def recent_logs( + *, + user_id: int, + limit: int = 50, + model: str | None = None, +) -> list[dict]: + """Return recent generation_tool_log rows for the user, newest first. + + Optionally filter to a specific model. Returns plain dicts so callers + don't need an open session to read fields. + """ + async with async_session() as session: + stmt = select(GenerationToolLog).where(GenerationToolLog.user_id == user_id) + if model: + stmt = stmt.where(GenerationToolLog.model == model) + stmt = stmt.order_by(GenerationToolLog.created_at.desc()).limit(limit) + result = await session.execute(stmt) + return [row.to_dict() for row in result.scalars().all()] diff --git a/src/fabledassistant/services/generation_task.py b/src/fabledassistant/services/generation_task.py index a92af60..401ccb5 100644 --- a/src/fabledassistant/services/generation_task.py +++ b/src/fabledassistant/services/generation_task.py @@ -480,6 +480,23 @@ async def run_generation( except Exception: logger.warning("Failed to persist generation timing for conv %d", conv_id, exc_info=True) + # Per-turn tool-call telemetry. Empirical surface for evaluating + # model swaps without needing user reports — answers "did model X + # actually fire record_moment when it should have?" The helper is + # internally try/except so this never affects the user-facing flow. + from fabledassistant.services.generation_log import log_tool_outcomes + await log_tool_outcomes( + user_id=user_id, + conv_id=conv_id, + assistant_message_id=msg_id, + model=model, + think_enabled=think, + tools_available=[ + (t.get("function") or {}).get("name") for t in tools + ], + tool_calls=all_tool_calls, + ) + buf.state = GenerationState.COMPLETED buf.finished_at = time.monotonic() done_payload: dict = {"done": True, "message_id": msg_id, "timing": timing} diff --git a/tests/test_generation_log.py b/tests/test_generation_log.py new file mode 100644 index 0000000..8dada22 --- /dev/null +++ b/tests/test_generation_log.py @@ -0,0 +1,180 @@ +"""Unit tests for the tool-call telemetry normalization logic. + +The DB-touching path of `log_tool_outcomes` requires a running PostgreSQL, +so we test the pure normalization by stubbing the session. The shape +contract that `generation_task.py` actually emits is: + + {"function": , "arguments": ..., "result": , "status": ...} + +with `result["success"]` being False for failures and `result["error"]` +the message. We verify the helper splits these correctly into the +attempted / succeeded / failed buckets. +""" +from __future__ import annotations + +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest + + +@pytest.mark.asyncio +async def test_log_tool_outcomes_splits_success_and_failure(): + """A mix of success and error entries should split into the right buckets.""" + captured: dict = {} + + class _StubSession: + def __init__(self): + self.added = [] + + async def __aenter__(self): + return self + + async def __aexit__(self, *exc): + return False + + def add(self, row): + self.added.append(row) + captured["row"] = row + + async def commit(self): + return None + + stub = _StubSession() + + from fabledassistant.services import generation_log + + with patch.object(generation_log, "async_session", lambda: stub): + await generation_log.log_tool_outcomes( + user_id=1, + conv_id=42, + assistant_message_id=99, + model="qwen3:8b", + think_enabled=False, + tools_available=["record_moment", "search_notes", "create_task"], + tool_calls=[ + { + "function": "record_moment", + "arguments": {}, + "result": {"success": True, "moment_id": 17}, + "status": "success", + }, + { + "function": "create_task", + "arguments": {}, + "result": {"success": False, "error": "missing required field 'title'"}, + "status": "error", + }, + ], + ) + + row = captured["row"] + assert row.user_id == 1 + assert row.conv_id == 42 + assert row.assistant_message_id == 99 + assert row.model == "qwen3:8b" + assert row.think_enabled is False + assert row.tools_available == ["create_task", "record_moment", "search_notes"] + assert row.tools_attempted == ["record_moment", "create_task"] + assert row.tools_succeeded == ["record_moment"] + assert row.tools_failed == [{"name": "create_task", "error": "missing required field 'title'"}] + + +@pytest.mark.asyncio +async def test_log_tool_outcomes_handles_empty_tool_calls(): + """A turn with no tool calls produces an empty-attempted row, not an exception.""" + captured: dict = {} + + class _StubSession: + async def __aenter__(self): + return self + + async def __aexit__(self, *exc): + return False + + def add(self, row): + captured["row"] = row + + async def commit(self): + return None + + from fabledassistant.services import generation_log + + with patch.object(generation_log, "async_session", lambda: _StubSession()): + await generation_log.log_tool_outcomes( + user_id=1, + conv_id=42, + assistant_message_id=99, + model="mistral-small:22b", + think_enabled=False, + tools_available=["record_moment"], + tool_calls=[], + ) + + row = captured["row"] + assert row.tools_attempted == [] + assert row.tools_succeeded == [] + assert row.tools_failed == [] + + +@pytest.mark.asyncio +async def test_log_tool_outcomes_swallows_exceptions(): + """Telemetry failure must NOT propagate — it would break user-facing flow.""" + from fabledassistant.services import generation_log + + bad_session = MagicMock() + bad_session.return_value.__aenter__ = AsyncMock(side_effect=RuntimeError("db down")) + + with patch.object(generation_log, "async_session", bad_session): + # Should NOT raise. + await generation_log.log_tool_outcomes( + user_id=1, + conv_id=42, + assistant_message_id=99, + model="qwen3:8b", + think_enabled=False, + tools_available=[], + tool_calls=[], + ) + + +@pytest.mark.asyncio +async def test_log_tool_outcomes_detects_success_false_without_error_field(): + """A tool result with success=False but no error string should still go to failed.""" + captured: dict = {} + + class _StubSession: + async def __aenter__(self): + return self + + async def __aexit__(self, *exc): + return False + + def add(self, row): + captured["row"] = row + + async def commit(self): + return None + + from fabledassistant.services import generation_log + + with patch.object(generation_log, "async_session", lambda: _StubSession()): + await generation_log.log_tool_outcomes( + user_id=1, + conv_id=42, + assistant_message_id=99, + model="qwen3:8b", + think_enabled=False, + tools_available=["search_notes"], + tool_calls=[ + { + "function": "search_notes", + "arguments": {}, + "result": {"success": False}, # no explicit error field + "status": "success", # but status incorrectly says success + }, + ], + ) + + row = captured["row"] + assert row.tools_succeeded == [] + assert row.tools_failed == [{"name": "search_notes", "error": "unspecified"}]