bvandeusen/FabledScribe
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 50 Wiki Activity

feat(llm): per-turn tool-call telemetry (generation_tool_log)

Browse Source 
Adds an empirical surface for evaluating model swaps. One row per
assistant turn captures: model, think_enabled, tools_available,
tools_attempted, tools_succeeded, tools_failed (with error details
as JSONB). Without this, judging whether a new model "actually fires
record_moment when it should" relies on anecdote across user-reported
sessions. With it, the data is queryable directly.

Pieces:
- Migration 0046: generation_tool_log table with user_created and
  per-conversation indexes.
- Model: SQLAlchemy GenerationToolLog with to_dict() for plain-dict
  consumption outside session scope.
- Service: log_tool_outcomes() normalizes the in-app tool-call shape
  (function/result/status) into the split buckets and persists. It
  catches its own exceptions — telemetry failure must NEVER affect
  the user-facing generation flow. recent_logs() helper for read.
- Integration in run_generation: called once per turn right after
  log_generation, fire-and-forget.
- Tests: pure-normalization unit tests using a stub session — no DB
  needed in CI. Cover the success/error split, the empty-tool-calls
  case, the exception-swallowing contract, and the success=False
  edge case where status incorrectly says "success".

No UI for the telemetry yet — internal infrastructure (the operator
is the consumer, not the journal user), which the FabledRulebook
"no UI no ship" explicitly excepts. Query via psql or extend the
Fable MCP later if direct shell access gets tiresome.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
Bryan Van Deusen
2026-05-21 22:04:09 -04:00
parent d345b32856
commit bf7a29e8a0
6 changed files with 487 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
alembic/versions/0046_add_generation_tool_log.py
+103
View File
@@ -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")
src/fabledassistant/models/__init__.py
+1
View File
@@ -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
src/fabledassistant/models/generation_tool_log.py
+75
View File
@@ -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,
}
src/fabledassistant/services/generation_log.py
+111
View File
@@ -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": <name>, "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()]
src/fabledassistant/services/generation_task.py
+17
View File
@@ -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}
tests/test_generation_log.py
+180
View File
@@ -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": <name>, "arguments": ..., "result": <dict>, "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"}]