Files
FabledScribe/tests/test_generation_log.py
T
bvandeusen bf7a29e8a0 feat(llm): per-turn tool-call telemetry (generation_tool_log)
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>
2026-05-21 22:04:09 -04:00

181 lines
5.6 KiB
Python

"""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"}]