Compare commits

...
Author SHA1 Message Date
rsp2k 99074c6fa8 Release 2026.09.29: events
Tests / test (==2.12.2) (push) Canceled after 0s
Tests / test (==2.14.3) (push) Canceled after 0s
Tests / test (>=3.3,<4) (push) Canceled after 0s
Tests / test (>=4,<5) (push) Canceled after 0s
Tests / canary (push) Canceled after 0s
2026-09-29 10:24:09 -06:00
rsp2k d998256bc4 Make event attrs JSON-safe on every write path, not only record_event 2026-09-29 10:23:38 -06:00
rsp2k bf62650e05 Add events: record_event, record_llm_call and an events table
Events are things worth recording that are not tool calls, such as a
background job changing state or an LLM request made by a tool. They go
through the same queue as call records, are redacted the same way, link
to the running tool call when there is one, and can be recorded from any
thread. DatabaseSink writes them to {prefix}events and prunes them with
the same retention; events_for(key) reads them back.
2026-09-29 10:22:05 -06:00
rsp2k b34f5683a1 Merge feature/retention-sampling: retention, exclusion and sampling
Tests / test (==2.12.2) (push) Canceled after 0s
Tests / test (==2.14.3) (push) Canceled after 0s
Tests / test (>=3.3,<4) (push) Canceled after 0s
Tests / test (>=4,<5) (push) Canceled after 0s
Tests / canary (push) Canceled after 0s
2026-09-28 22:13:07 -06:00
14 changed files with 1270 additions and 60 deletions
+65
View File
@@ -5,6 +5,71 @@ All notable changes to this project will be documented in this file.
The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/),
and this project adheres to [Calendar Versioning](https://calver.org/) (YYYY.MM.DD).
## [2026.09.29] - 2026-09-29
Record things that are not tool calls: background job transitions, LLM
requests a tool makes, anything with a dotted name.
### Added
- `mw.record_event(kind, *, key=None, attrs=None, user_sub=None,
call_id=None) -> bool`. Synchronous; never raises, never blocks. `attrs` is
redacted like call arguments and made JSON-safe (`NaN`/infinities become
strings, since Postgres JSONB rejects them). Returns False when the event
was not recorded: mode `off`, an empty or over-128-character `kind`, a `key`
over 255 characters, non-mapping `attrs`, a full queue, or no event loop.
Events share the call records' queue and drop-and-count policy.
- **Linking to the running call.** The middleware now picks a call's record id
before the tool runs and exposes it through a ContextVar, so an event
recorded inside a tool gets that call's id as `call_id` (and its session),
matching the stored `ffb_tool_calls` row. Outside a call, `call_id` is None;
a task a tool started that records after the tool returned counts as
outside.
- **Thread safety.** `record_event` works from any thread: off the server's
loop, the event is handed over with `call_soon_threadsafe`. The loop is
known from the first tool call (the dispatcher now binds to it as each call
starts), so sync tools running in FastMCP's worker threads link too. Before
any call or record, a thread with no loop of its own gets False and a
counted drop.
- `mw.record_llm_call(*, model, provider=None, duration_ms=None,
input_tokens=None, output_tokens=None, ok=None, error=None, key=None,
attrs=None) -> bool` records kind `llm.call` with plain attribute names:
`model`, `provider`, `duration_ms`, `input_tokens`, `output_tokens`, `ok`
(defaults to `error is None`), `error` (redacted, truncated to
`max_error_chars`) and `error_type` for exceptions. The README maps them to
OTel GenAI names.
- `await mw.events_for(key, *, kinds=None, limit=1000)`: a key's events, oldest
first (the newest `limit`), from the `DatabaseSink` plus events still in the
queue, deduplicated by id, `occurred_at` in UTC. Without a `DatabaseSink` it
answers from memory (`recent_events=2000` on the middleware).
- `EventRecord`, exported from `fastmcp_feedback.instrumentation`.
`MemorySink` has `.calls` and `.events`.
- Exclusion and sampling still apply to tool calls only. A sampled tool's call
that recorded an event is always kept (no `sample_rate`), so the event's
`call_id` has a row.
### Changed
- Sinks receive mixed batches of `ToolCallRecord` and `EventRecord` once
events are recorded. `record.record_type` is `tool_call` or `event`. A
`CallbackSink` callback that assumes every record is a call needs a check.
- `JsonLinesSink` lines carry `"record": "tool_call"` or `"record": "event"`
(a new field; existing fields unchanged).
- `DatabaseSink.write` stores calls and events in separate transactions,
calls first, so a database without the events table still stores calls.
- `DatabaseSink.prune()` also deletes events whose `occurred_at` is before
the cutoff, in `prune_batch` batches, and **returns the total rows deleted
from both tables**; each table's count is logged. It skips events on a
database that has no events table.
### Migration
- New table `{prefix}events` (`ffb_events` by default): `id`, `occurred_at`,
`kind`, `key`, `call_id`, `session_id`, `user_sub`, `caller_kind`,
`client_id`, `server_version`, `attrs` (JSON/JSONB), indexed on
`occurred_at`, `kind`, `key`, `call_id` and `user_sub`. Hosts that manage the
schema with Alembic need a migration creating it (`build_metadata()`
includes it). `create_tables=True` creates it on first use. Until it exists,
event writes fail and are dropped (logged); calls are unaffected. No change
to existing tables.
## [2026.09.28] - 2026-09-28
Keep the tool-call table small: leave out or sample busy tools, and prune old
+126 -2
View File
@@ -185,8 +185,9 @@ instrument(app, [
### Using your own database and migrations
Pass the `AsyncEngine` you already have. Records go to a `ffb_tool_calls`
table (the prefix is configurable), and nothing is created at startup unless you
ask. To manage the table with Alembic, add it to your `env.py`:
table (events to `ffb_events`; the prefix is configurable), and nothing is
created at startup unless you ask. To manage the tables with Alembic, add them
to your `env.py`:
```python
from fastmcp_feedback.instrumentation import build_metadata
@@ -410,6 +411,129 @@ on Postgres also works), since existing tables are not altered. Until the
column exists, database writes fail and those records are dropped (logged).
Retention needs no schema change.
### Events: things that aren't tool calls
Some things worth recording happen outside a tool call, or inside one without
being one: a background job changing state minutes after the tool that
started it returned, or an LLM request a tool makes on the caller's behalf.
Record them as events:
```python
from fastmcp_feedback.instrumentation import DatabaseSink, instrument
mw = instrument(app, [DatabaseSink("sqlite+aiosqlite:///calls.db", create_tables=True)])
@app.tool
async def submit(case: str) -> dict:
job_id = f"job-{case}"
mw.record_event("job.submitted", key=job_id, attrs={"case": case, "nproc": 8})
return {"job_id": job_id}
# Later, from a watcher task or thread, with no tool call running:
mw.record_event("job.finished", key="job-wing", attrs={"duration_s": 3512, "converged": True})
```
`record_event(kind, *, key=None, attrs=None, user_sub=None, call_id=None)`
returns True when the event was queued and False when it was not. It never
raises and never blocks, and it takes the same path as call records: the same
background queue, the same drop-and-count policy when the queue is full.
- `kind` is a dotted name (`job.submitted`, `llm.call`), a non-empty string of
at most 128 characters.
- `key` is what you join on, such as a job id. It is stored as a string, at
most 255 characters.
- `attrs` is any JSON-like dict. It is redacted like call arguments, then made
JSON-safe: `NaN` and infinities become the strings `"nan"`/`"inf"` (Postgres
JSONB rejects them), datetimes become ISO strings, anything else unknown
becomes `str(value)`.
- **Inside a tool call**, the event gets that call's id as `call_id` and its
session, so it joins to the call's row in `ffb_tool_calls`. Outside a call,
`call_id` is None. A task started by a tool that records after the tool has
returned counts as outside. Pass `call_id=` to set it yourself.
- **From any thread.** Called off the server's event loop (a watcher thread, a
sync tool running in a worker thread), the event is handed to the loop with
`call_soon_threadsafe`. The loop is known once the server has handled a tool
call or recorded something on it; before that, a call from a thread with no
event loop of its own returns False and counts a drop.
- In mode `off` it does nothing and returns False.
Read a key's events back, oldest first, with `occurred_at` as UTC:
```python
for ev in await mw.events_for("job-wing"):
print(ev["occurred_at"], ev["kind"], ev["call_id"], ev["attrs"])
steps = await mw.events_for("job-wing", kinds=["step.started", "step.finished"], limit=100)
```
`events_for` reads the `DatabaseSink` and adds events still waiting in the
queue, so an event is visible as soon as `record_event` returns. With more
than `limit` (1000) matches it returns the newest `limit`. Without a
`DatabaseSink` it answers from the last `recent_events` (2000) events in
memory; a failing database read is logged and memory is used.
#### LLM calls
`record_llm_call` records an event of kind `llm.call`. Call it from inside the
tool that made the request and it links to that call:
```python
mw.record_llm_call(
model="claude-opus-4",
provider="anthropic",
duration_ms=812.5,
input_tokens=1200,
output_tokens=90,
attrs={"cache_read_input_tokens": 1000},
)
```
Its attributes use plain names, which are easier to query from SQL than
dotted ones (`attrs->>'model'` on Postgres, `json_extract(attrs, '$.model')`
on SQLite):
| Attribute | OTel GenAI equivalent | Notes |
|-----------|-----------------------|-------|
| `model` | `gen_ai.request.model` | Always set |
| `provider` | `gen_ai.provider.name` | When given |
| `duration_ms` | `gen_ai.client.operation.duration` (seconds) | When given |
| `input_tokens` | `gen_ai.usage.input_tokens` | When given |
| `output_tokens` | `gen_ai.usage.output_tokens` | When given |
| `ok` | | Defaults to `error is None` |
| `error` | | Redacted, truncated to `max_error_chars` |
| `error_type` | `error.type` | When `error` is an exception |
Anything in `attrs` is kept alongside, but these names win. `key=` works as
for `record_event`, for example a chat turn id.
#### Storage and sinks
Events go to a `ffb_events` table: `id`, `occurred_at`, `kind`, `key`,
`call_id`, `session_id`, `user_sub`, `caller_kind`, `client_id`,
`server_version`, `attrs` (JSON; JSONB on Postgres), indexed on
`occurred_at`, `kind`, `key`, `call_id` and `user_sub`. It has no foreign key
to `ffb_tool_calls`, since calls are pruned and may be written later.
Sinks get calls and events in the same batches. `DatabaseSink` writes each to
its table, calls first in their own transaction, so a database without
`ffb_events` still stores calls. `JsonLinesSink` adds `"record": "tool_call"`
or `"record": "event"` to every line. A `CallbackSink` callback receives both
kinds (`record.record_type` tells them apart), and `MemorySink` has `.calls`
and `.events` next to `.records`.
Retention covers events too: `prune()` deletes events whose `occurred_at` is
before the cutoff, in the same batches, and returns the rows deleted from both
tables (each table's count is logged). Exclusion and sampling apply to tool
calls only; events are always recorded. A call of a sampled tool that recorded
an event is always kept, with no `sample_rate`, so the event's `call_id` has a
row to join to. Events recorded inside an excluded tool have no `call_id`.
**Upgrading:** `ffb_events` is a new table in this release. Hosts that manage
the schema with Alembic need a migration creating it (`build_metadata()`
includes it). `create_tables=True` creates it on first use, since it creates
missing tables. Until the table exists, event writes fail and those events
are dropped (logged); tool calls and pruning are unaffected.
### Middleware order and shutdown
FastMCP runs the first middleware added as the outermost. Call `instrument()`
+1 -1
View File
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
[project]
name = "fastmcp-feedback"
version = "2026.09.28" # YYYYMMDD.patch versioning - update for each release
version = "2026.09.29" # YYYYMMDD.patch versioning - update for each release
description = "Production-ready feedback collection system for FastMCP servers"
readme = "README.md"
license = "MIT"
+1 -1
View File
@@ -44,7 +44,7 @@ Quick Start:
import logging
# Version information - CalVer YYYY.MM.DD
__version__ = "2026.09.28"
__version__ = "2026.09.29"
__author__ = "Ryan Malloy"
__email__ = "ryan@supported.systems"
@@ -5,6 +5,7 @@ from fastmcp_feedback.instrumentation import instrument, DatabaseSink
mw = instrument(app) # every tool call as JSON lines on stderr
mw = instrument(app, [DatabaseSink(engine)], identity_resolver=who)
mw = instrument(app, result_classifier=soft_error_classifier(extra_statuses=("unknown_target",)))
mw.record_event("job.finished", key=job_id, attrs={"duration_s": 3600})
"""
from .classify import (
@@ -13,6 +14,7 @@ from .classify import (
soft_error_classifier,
)
from .dispatch import RecordDispatcher
from .events import EventRecord
from .middleware import MODE_ENV_VAR, MODES, InstrumentationMiddleware, instrument
from .record import ToolCallRecord
from .redaction import (
@@ -31,6 +33,7 @@ __all__ = [
"DEFAULT_SECRET_KEYS",
"DEFAULT_SECRET_PATTERNS",
"DEFAULT_TABLE_PREFIX",
"EventRecord",
"InstrumentationMiddleware",
"JsonLinesSink",
"MemorySink",
@@ -3,10 +3,10 @@
import asyncio
import contextlib
import logging
from collections.abc import Sequence
import threading
from collections.abc import Callable, Sequence
from .record import ToolCallRecord
from .sinks import Sink
from .sinks import Record, Sink
logger = logging.getLogger(__name__)
@@ -33,11 +33,13 @@ class RecordDispatcher:
self.sink_timeout = sink_timeout
self.dropped = 0
self.sink_errors = 0
self._queue: asyncio.Queue[ToolCallRecord] | None = None
self._queue: asyncio.Queue[Record] | None = None
self._task: asyncio.Task | None = None
self._loop: asyncio.AbstractEventLoop | None = None
# submit_threadsafe can drop from any thread.
self._drop_lock = threading.Lock()
def submit(self, record: ToolCallRecord) -> bool:
def submit(self, record: Record) -> bool:
"""Queue a record for delivery. Returns False if it was dropped."""
try:
loop = asyncio.get_running_loop()
@@ -45,12 +47,7 @@ class RecordDispatcher:
self._drop("no running event loop")
return False
# A queue belongs to one loop; tests and some hosts run several.
if self._queue is None or self._loop is not loop:
self._loop = loop
self._queue = asyncio.Queue(maxsize=self.max_queue)
self._task = loop.create_task(self._run(self._queue))
self._bind(loop)
try:
self._queue.put_nowait(record)
except asyncio.QueueFull:
@@ -58,11 +55,79 @@ class RecordDispatcher:
return False
return True
def bind_loop(self) -> None:
"""Adopt the running loop, so other threads can submit before any record.
Called by the middleware as each tool call starts. Never raises.
"""
with contextlib.suppress(Exception):
self._bind(asyncio.get_running_loop())
def _bind(self, loop: asyncio.AbstractEventLoop) -> None:
# A queue belongs to one loop; tests and some hosts run several.
if self._queue is None or self._loop is not loop:
self._loop = loop
self._queue = asyncio.Queue(maxsize=self.max_queue)
self._task = loop.create_task(self._run(self._queue))
def submit_threadsafe(
self,
record: Record,
on_queued: Callable[[Record], None] | None = None,
) -> bool:
"""``submit`` that may be called from any thread. Never blocks or raises.
On the loop the dispatcher runs on, or on any loop when it has none
running, this is ``submit``. From another thread the record is handed
to the dispatcher's loop with ``call_soon_threadsafe``; True then means
it was handed over, and a queue that fills before it lands still drops
and counts it. With no running loop anywhere the record is dropped.
``on_queued(record)`` runs on the loop thread once the record is queued.
"""
try:
try:
running = asyncio.get_running_loop()
except RuntimeError:
running = None
home = self._loop
home_alive = home is not None and home.is_running()
if running is not None and (not home_alive or home is running):
return self._submit_and_notify(record, on_queued)
if not home_alive:
self._drop("no running event loop")
return False
queue = self._queue
if queue is not None and queue.full():
self._drop("queue full")
return False
home.call_soon_threadsafe(self._submit_and_notify, record, on_queued)
return True
except Exception:
# call_soon_threadsafe raises if the loop closed after the check.
self._drop("event loop unavailable")
return False
def _submit_and_notify(
self, record: Record, on_queued: Callable[[Record], None] | None
) -> bool:
if not self.submit(record):
return False
if on_queued is not None:
try:
on_queued(record)
except Exception:
logger.warning("on_queued callback failed", exc_info=True)
return True
def _drop(self, reason: str) -> None:
self.dropped += 1
if self.dropped == 1 or self.dropped % 1000 == 0:
with self._drop_lock:
self.dropped += 1
dropped = self.dropped
if dropped == 1 or dropped % 1000 == 0:
logger.warning(
"Dropped tool-call record (%s); %d dropped so far", reason, self.dropped
"Dropped instrumentation record (%s); %d dropped so far",
reason,
dropped,
)
async def _run(self, queue: asyncio.Queue) -> None:
@@ -79,7 +144,7 @@ class RecordDispatcher:
for _ in batch:
queue.task_done()
async def _deliver(self, batch: list[ToolCallRecord]) -> None:
async def _deliver(self, batch: list[Record]) -> None:
for sink in self.sinks:
try:
await asyncio.wait_for(sink.write(batch), self.sink_timeout)
@@ -0,0 +1,89 @@
"""Events: things worth recording that are not tool calls.
A background job changing state, an LLM request made on a tool's behalf. Each
event has a dotted ``kind``, an optional ``key`` to join on (a job id), and,
when recorded while a tool call is running, that call's id.
"""
import math
import uuid
from dataclasses import asdict, dataclass, field
from datetime import datetime
from typing import Any, ClassVar
# Column widths in {prefix}events. Longer values are refused rather than
# truncated, since a cut key would silently stop joining.
MAX_KIND_CHARS = 128
MAX_KEY_CHARS = 255
@dataclass
class EventRecord:
"""One event, as passed to sinks next to ``ToolCallRecord``.
``call_id`` is the id of the tool call that was running when the event was
recorded, None outside a call. ``attrs`` is already redacted.
"""
record_type: ClassVar[str] = "event"
kind: str
occurred_at: datetime
id: str = field(default_factory=lambda: str(uuid.uuid4()))
key: str | None = None
call_id: str | None = None
session_id: str | None = None
user_sub: str | None = None
caller_kind: str | None = None
client_id: str | None = None
server_version: str | None = None
attrs: dict[str, Any] = field(default_factory=dict)
def to_row(self) -> dict[str, Any]:
"""Column values for the events table, with ``attrs`` made JSON-safe."""
data = asdict(self)
data["attrs"] = jsonable(data["attrs"])
return data
def to_dict(self) -> dict[str, Any]:
"""JSON-friendly form, with the timestamp as ISO 8601."""
data = self.to_row()
data["occurred_at"] = self.occurred_at.isoformat()
return data
@dataclass
class CallScope:
"""The tool call in progress, visible to ``record_event`` through a ContextVar.
Tasks started inside a tool inherit a copy of the context and outlive the
call, so the scope is switched off when the call ends instead of relying
on the ContextVar reset alone.
"""
id: str
session_id: str | None
active: bool = True
events: int = 0
def jsonable(value: Any, depth: int = 0) -> Any:
"""A copy of ``value`` that any JSON column accepts.
Non-finite floats (a diverged residual) become strings, since Postgres
JSONB rejects NaN and one bad row would fail the whole batch. Other
unknown types become ``str(value)``.
"""
if depth > 32:
return "[TRUNCATED]"
if value is None or isinstance(value, bool | int | str):
return value
if isinstance(value, float):
return value if math.isfinite(value) else str(value)
if isinstance(value, dict):
return {str(k): jsonable(v, depth + 1) for k, v in value.items()}
if isinstance(value, list | tuple | set | frozenset):
return [jsonable(v, depth + 1) for v in value]
if isinstance(value, datetime):
return value.isoformat()
return str(value)
@@ -1,6 +1,8 @@
"""FastMCP middleware that records every tool call."""
"""FastMCP middleware that records every tool call, and events you report."""
import asyncio
import contextlib
import contextvars
import inspect
import json
import logging
@@ -25,6 +27,13 @@ from .correlation import (
select_calls,
)
from .dispatch import RecordDispatcher
from .events import (
MAX_KEY_CHARS,
MAX_KIND_CHARS,
CallScope,
EventRecord,
jsonable,
)
from .record import ToolCallRecord
from .redaction import Redactor
from .sinks import JsonLinesSink, Sink
@@ -150,6 +159,12 @@ class InstrumentationMiddleware(Middleware):
sampled out are not kept for correlation either.
random: ``() -> float`` in [0, 1) deciding sampling; a call is kept
when it returns less than the tool's rate. For tests.
recent_events: how many recent events to keep in memory for
``events_for``, including ones still waiting to reach the sinks.
Exclusion and sampling apply to tool calls only; events are always
recorded. A sampled tool's call is kept whenever an event was recorded
during it, so the event's ``call_id`` always has a row.
"""
def __init__(
@@ -173,6 +188,7 @@ class InstrumentationMiddleware(Middleware):
exclude_tools: Iterable[str] = (),
sample_rates: Mapping[str, float] | None = None,
random: Callable[[], float] = _random.random,
recent_events: int = 2000,
):
mode = (mode or os.getenv(MODE_ENV_VAR) or "meta").lower()
if mode not in MODES:
@@ -198,6 +214,11 @@ class InstrumentationMiddleware(Middleware):
self.sample_rates[tool] = rate
self.random = random
self.recent: deque[ToolCallRecord] = deque(maxlen=recent_calls)
self.recent_events: deque[EventRecord] = deque(maxlen=recent_events)
# One per middleware, so events only link to calls this one records.
self._call_scope: contextvars.ContextVar[CallScope | None] = (
contextvars.ContextVar(f"ffb_call_scope_{id(self):x}", default=None)
)
self.dispatcher = RecordDispatcher(
sinks if sinks is not None else [JsonLinesSink()],
max_queue=max_queue,
@@ -208,6 +229,8 @@ class InstrumentationMiddleware(Middleware):
async def on_call_tool(self, context: MiddlewareContext, call_next):
if self.mode == "off":
return await call_next(context)
# Sync tools run in worker threads; their events need the loop known.
self.dispatcher.bind_loop()
if _tool_name(context) in self.exclude_tools:
return await call_next(context)
@@ -215,6 +238,16 @@ class InstrumentationMiddleware(Middleware):
start = time.perf_counter()
result = None
error: BaseException | None = None
scope = token = None
try:
# The record id exists before the tool runs, so events recorded
# inside it carry the id the stored call row will have.
scope = CallScope(
id=str(uuid.uuid4()), session_id=session_key(context.fastmcp_context)
)
token = self._call_scope.set(scope)
except Exception:
logger.warning("Failed to open call scope", exc_info=True)
try:
result = await call_next(context)
return result
@@ -223,8 +256,16 @@ class InstrumentationMiddleware(Middleware):
raise
finally:
duration_ms = (time.perf_counter() - start) * 1000
if scope is not None:
scope.active = False
if token is not None:
# ValueError when finishing in another context (a task group).
with contextlib.suppress(ValueError):
self._call_scope.reset(token)
try:
await self._record(context, started_at, duration_ms, result, error)
await self._record(
context, started_at, duration_ms, result, error, scope
)
except Exception:
logger.warning("Failed to record tool call", exc_info=True)
@@ -235,6 +276,7 @@ class InstrumentationMiddleware(Middleware):
duration_ms: float,
result: Any,
error: BaseException | None,
scope: CallScope | None = None,
) -> None:
tool = _tool_name(context)
payload = _result_payload(result) if result is not None else None
@@ -242,14 +284,19 @@ class InstrumentationMiddleware(Middleware):
if error is None and self.result_classifier is not None and payload is not None:
soft = self._classify(tool, result, payload)
rate = self.sample_rates.get(tool)
# Failures are always kept, and their rows carry no sample_rate.
if rate is not None and (error is not None or soft is not None):
# Failures are always kept, and their rows carry no sample_rate. So are
# calls that recorded events, which would otherwise point at nothing.
if rate is not None and (
error is not None or soft is not None or (scope and scope.events)
):
rate = None
elif rate is not None and not self.random() < rate:
return
record = await self._build_record(
context, started_at, duration_ms, payload, error, soft, rate
)
if scope is not None:
record.id = scope.id
self.recent.append(record)
self.dispatcher.submit(record)
@@ -348,6 +395,144 @@ class InstrumentationMiddleware(Middleware):
sample_rate=sample_rate,
)
def record_event(
self,
kind: str,
*,
key: Any = None,
attrs: Mapping[str, Any] | None = None,
user_sub: str | None = None,
call_id: str | None = None,
) -> bool:
"""Record something that is not a tool call. Never raises or blocks.
Safe from any thread. Inside a tool call the event gets that call's id
and session; ``call_id`` given here wins. ``attrs`` is redacted like
call arguments and made JSON-safe. ``kind`` must be a non-empty string
of at most 128 characters and ``key`` at most 255 once made a string.
Returns False when the event was not recorded: mode ``off``, an invalid
``kind``, ``key`` or ``attrs``, a full queue, or no event loop to hand
it to (called from a thread before anything was recorded on the
server's loop). From another thread, True means handed to the loop.
"""
try:
if self.mode == "off":
return False
if not isinstance(kind, str) or not kind.strip():
logger.warning("record_event needs a non-empty str kind, got %r", kind)
return False
if len(kind) > MAX_KIND_CHARS:
logger.warning(
"Event kind longer than %d chars: %r", MAX_KIND_CHARS, kind
)
return False
if key is not None:
key = str(key)
if len(key) > MAX_KEY_CHARS:
logger.warning("Event key longer than %d chars", MAX_KEY_CHARS)
return False
if attrs is not None and not isinstance(attrs, Mapping):
logger.warning("Event attrs must be a mapping, got %s", type(attrs))
return False
session_id = None
scope = self._call_scope.get()
if scope is not None and scope.active:
scope.events += 1
session_id = scope.session_id
if call_id is None:
call_id = scope.id
record = EventRecord(
kind=kind,
occurred_at=datetime.now(UTC),
key=key,
call_id=None if call_id is None else str(call_id),
session_id=session_id,
user_sub=None if user_sub is None else str(user_sub),
server_version=self.server_version,
attrs=jsonable(self.redactor.redact(dict(attrs or {}))),
)
return self.dispatcher.submit_threadsafe(record, self.recent_events.append)
except Exception:
logger.warning("Failed to record event %r", kind, exc_info=True)
return False
def record_llm_call(
self,
*,
model: str,
provider: str | None = None,
duration_ms: float | None = None,
input_tokens: int | None = None,
output_tokens: int | None = None,
ok: bool | None = None,
error: str | BaseException | None = None,
key: Any = None,
attrs: Mapping[str, Any] | None = None,
) -> bool:
"""Record one LLM request as an ``llm.call`` event. Never raises.
Attributes: ``model``, ``provider``, ``duration_ms``, ``input_tokens``,
``output_tokens`` (each only when given), ``ok``, and on failure
``error`` (redacted, truncated to ``max_error_chars``) plus
``error_type`` when ``error`` is an exception. ``ok`` defaults to
``error is None``. Extra ``attrs`` are kept, but these names win.
"""
try:
fields: dict[str, Any] = dict(attrs or {})
fields["model"] = None if model is None else str(model)
for name, value in (
("provider", provider),
("duration_ms", duration_ms),
("input_tokens", input_tokens),
("output_tokens", output_tokens),
):
if value is not None:
fields[name] = value
fields["ok"] = (error is None) if ok is None else bool(ok)
if error is not None:
if isinstance(error, BaseException):
fields["error_type"] = type(error).__name__
text = self.redactor.redact_text(str(error))
fields["error"] = text[: self.max_error_chars]
return self.record_event("llm.call", key=key, attrs=fields)
except Exception:
logger.warning("Failed to record LLM call", exc_info=True)
return False
async def events_for(
self,
key: Any,
*,
kinds: Iterable[str] | None = None,
limit: int = 1000,
) -> list[dict[str, Any]]:
"""Events for ``key``, oldest first: the newest ``limit`` of them.
Reads the DatabaseSink when there is one and adds events still only in
memory, so an event is visible as soon as ``record_event`` returns (on
the loop thread). Without a DatabaseSink, memory only. ``occurred_at``
is a UTC datetime. A database failure is logged and memory is used.
"""
key = str(key)
kinds = None if kinds is None else frozenset(kinds)
found: dict[str, dict[str, Any]] = {}
sink = self.database_sink
if sink is not None:
try:
for row in await sink.events_for(key, kinds=kinds, limit=limit):
found[row["id"]] = row
except Exception:
logger.warning("Failed to read events for %r", key, exc_info=True)
for record in list(self.recent_events):
if record.key == key and (kinds is None or record.kind in kinds):
found.setdefault(record.id, record.to_row())
rows = list(found.values())
for row in rows:
row["occurred_at"] = as_utc(row["occurred_at"])
rows.sort(key=lambda r: r["occurred_at"])
return rows[-limit:] if limit > 0 else []
@property
def database_sink(self) -> DatabaseSink | None:
"""The first DatabaseSink among the sinks, if any."""
@@ -3,7 +3,7 @@
import uuid
from dataclasses import asdict, dataclass, field
from datetime import datetime
from typing import Any
from typing import Any, ClassVar
@dataclass
@@ -22,6 +22,8 @@ class ToolCallRecord:
unconditionally, including failures of sampled tools.
"""
record_type: ClassVar[str] = "tool_call"
tool: str
started_at: datetime
duration_ms: float
+34 -11
View File
@@ -1,4 +1,4 @@
"""Destinations for tool-call records."""
"""Destinations for tool-call and event records."""
import inspect
import json
@@ -6,27 +6,38 @@ import sys
from collections.abc import Callable, Sequence
from typing import IO, Any, Protocol, runtime_checkable
from .events import EventRecord
from .record import ToolCallRecord
Record = ToolCallRecord | EventRecord
@runtime_checkable
class Sink(Protocol):
"""Anything with ``async write(records)``. ``async aclose()`` is optional."""
"""Anything with ``async write(records)``. ``async aclose()`` is optional.
async def write(self, records: Sequence[ToolCallRecord]) -> None: ...
A batch can mix ``ToolCallRecord`` and ``EventRecord``; tell them apart
with ``isinstance`` or ``record.record_type`` (``tool_call``, ``event``).
"""
async def write(self, records: Sequence[Record]) -> None: ...
class JsonLinesSink:
"""One JSON object per record, to stderr by default."""
"""One JSON object per record, to stderr by default.
Each line has ``"record": "tool_call"`` or ``"record": "event"``.
"""
def __init__(self, stream: IO[str] | None = None):
self._stream = stream
async def write(self, records: Sequence[ToolCallRecord]) -> None:
async def write(self, records: Sequence[Record]) -> None:
# Resolved per write so a stderr swapped by the host or a test is honored.
stream = self._stream or sys.stderr
for record in records:
stream.write(json.dumps(record.to_dict(), default=str) + "\n")
line = {"record": record.record_type, **record.to_dict()}
stream.write(json.dumps(line, default=str) + "\n")
stream.flush()
@@ -36,20 +47,32 @@ class CallbackSink:
A sync callback runs on the event loop, so keep it quick.
"""
def __init__(self, callback: Callable[[Sequence[ToolCallRecord]], Any]):
def __init__(self, callback: Callable[[Sequence[Record]], Any]):
self.callback = callback
async def write(self, records: Sequence[ToolCallRecord]) -> None:
async def write(self, records: Sequence[Record]) -> None:
result = self.callback(records)
if inspect.isawaitable(result):
await result
class MemorySink:
"""Keep records in a list. Meant for tests."""
"""Keep records in a list. Meant for tests.
``records`` holds everything in arrival order; ``calls`` and ``events``
are the two kinds on their own.
"""
def __init__(self):
self.records: list[ToolCallRecord] = []
self.records: list[Record] = []
async def write(self, records: Sequence[ToolCallRecord]) -> None:
@property
def calls(self) -> list[ToolCallRecord]:
return [r for r in self.records if isinstance(r, ToolCallRecord)]
@property
def events(self) -> list[EventRecord]:
return [r for r in self.records if isinstance(r, EventRecord)]
async def write(self, records: Sequence[Record]) -> None:
self.records.extend(records)
+87 -22
View File
@@ -1,4 +1,4 @@
"""Async SQLAlchemy storage for tool-call records and feedback links.
"""Async SQLAlchemy storage for tool-call records, events and feedback links.
Hosts that manage their own schema include ``build_metadata(prefix)`` in their
Alembic ``env.py`` (``target_metadata``) and pass their existing AsyncEngine to
@@ -26,13 +26,16 @@ from sqlalchemy import (
and_,
delete,
exists,
inspect,
or_,
select,
)
from sqlalchemy.dialects.postgresql import JSONB
from sqlalchemy.ext.asyncio import AsyncEngine, create_async_engine
from .events import MAX_KEY_CHARS, MAX_KIND_CHARS, EventRecord
from .record import ToolCallRecord
from .sinks import Record
logger = logging.getLogger(__name__)
@@ -45,12 +48,14 @@ _JSON = JSON(none_as_null=True).with_variant(JSONB(none_as_null=True), "postgres
def build_metadata(
prefix: str = DEFAULT_TABLE_PREFIX, metadata: MetaData | None = None
) -> MetaData:
"""Return MetaData holding ``{prefix}tool_calls`` and ``{prefix}feedback_call_links``.
"""Return MetaData holding ``{prefix}tool_calls``, ``{prefix}events`` and
``{prefix}feedback_call_links``.
Pass an existing MetaData to add the tables to it instead.
"""
metadata = metadata if metadata is not None else MetaData()
calls = f"{prefix}tool_calls"
events = f"{prefix}events"
links = f"{prefix}feedback_call_links"
if calls not in metadata.tables:
Table(
@@ -82,6 +87,24 @@ def build_metadata(
# NULL for rows recorded unconditionally and before 2026.09.28.
Column("sample_rate", Float),
)
if events not in metadata.tables:
# No foreign key to tool_calls for the same reasons as links: an event
# can be written before its call leaves the queue, and calls are pruned.
Table(
events,
metadata,
Column("id", String(36), primary_key=True),
Column("occurred_at", DateTime(timezone=True), nullable=False, index=True),
Column("kind", String(MAX_KIND_CHARS), nullable=False, index=True),
Column("key", String(MAX_KEY_CHARS), index=True),
Column("call_id", String(36), index=True),
Column("session_id", String(255)),
Column("user_sub", String(255), index=True),
Column("caller_kind", String(64)),
Column("client_id", String(255)),
Column("server_version", String(64)),
Column("attrs", _JSON),
)
if links not in metadata.tables:
# No foreign key to tool_calls: a link can be written before its call
# record has left the queue, and hosts may keep calls elsewhere.
@@ -98,7 +121,7 @@ def build_metadata(
class DatabaseSink:
"""Write records to ``{prefix}tool_calls`` through an async engine.
"""Write records to ``{prefix}tool_calls`` and ``{prefix}events``.
Args:
engine: an AsyncEngine the host already owns, or a URL such as
@@ -108,7 +131,7 @@ class DatabaseSink:
prefix: table name prefix, so the tables cannot collide with the host's.
create_tables: create the tables on first use. Off by default; hosts
with Alembic should generate a migration from ``build_metadata``.
retention: delete tool-call rows older than this. When set, ``write``
retention: delete tool-call and event rows older than this. When set, ``write``
runs ``prune()`` at most once per ``prune_interval``, after its
insert, in the background writer. None (the default) keeps rows
forever. Calls linked to feedback are never pruned.
@@ -135,6 +158,7 @@ class DatabaseSink:
self.engine = create_async_engine(engine) if isinstance(engine, str) else engine
self.metadata = build_metadata(prefix)
self.table = self.metadata.tables[f"{prefix}tool_calls"]
self.events = self.metadata.tables[f"{prefix}events"]
self.links = self.metadata.tables[f"{prefix}feedback_call_links"]
self.create_tables = create_tables
self._tables_ready = False
@@ -159,12 +183,20 @@ class DatabaseSink:
if not self._tables_ready:
await self.ensure_tables()
async def write(self, records: Sequence[ToolCallRecord]) -> None:
if not records:
async def write(self, records: Sequence[Record]) -> None:
calls = [r.to_row() for r in records if isinstance(r, ToolCallRecord)]
events = [r.to_row() for r in records if isinstance(r, EventRecord)]
if not calls and not events:
return
await self._ready()
async with self.engine.begin() as conn:
await conn.execute(self.table.insert(), [r.to_row() for r in records])
# Separate transactions, calls first: a host that has not created the
# events table yet still gets its calls stored.
if calls:
async with self.engine.begin() as conn:
await conn.execute(self.table.insert(), calls)
if events:
async with self.engine.begin() as conn:
await conn.execute(self.events.insert(), events)
await self._auto_prune()
async def _auto_prune(self) -> None:
@@ -179,21 +211,20 @@ class DatabaseSink:
# Set before running, so a prune that fails is not retried every write.
self._last_prune = now
try:
deleted = await self.prune()
if deleted:
logger.info(
"Pruned %d tool-call rows from %s", deleted, self.table.name
)
await self.prune()
except Exception:
logger.warning("Pruning %s failed", self.table.name, exc_info=True)
async def prune(self, older_than: datetime | None = None) -> int:
"""Delete tool-call rows that started before ``older_than``.
"""Delete tool-call and event rows from before ``older_than``.
Defaults to now minus ``retention``; with neither, deletes nothing.
Calls linked to feedback in ``{prefix}feedback_call_links`` are kept,
and links are never deleted. Deletes ``prune_batch`` rows per
transaction until none are left. Returns the number of rows deleted.
and links are never deleted. Events go by ``occurred_at``, whatever
call they belong to. Deletes ``prune_batch`` rows per transaction until
none are left. Returns the total rows deleted from both tables and
logs each table's count. A database without the events table (not yet
migrated) has its calls pruned and the events step skipped.
"""
if older_than is None:
if self.retention is None:
@@ -201,24 +232,58 @@ class DatabaseSink:
older_than = datetime.now(UTC) - self.retention
await self._ready()
t, link = self.table, self.links
batch = (
select(t.c.id)
.where(
calls = await self._delete_batches(
t,
select(t.c.id).where(
t.c.started_at < older_than,
~exists().where(link.c.call_id == t.c.id),
)
.limit(self.prune_batch)
),
)
events = 0
if await self._has_table(self.events.name):
e = self.events
events = await self._delete_batches(
e, select(e.c.id).where(e.c.occurred_at < older_than)
)
if calls or events:
logger.info(
"Pruned %d rows from %s and %d from %s",
calls,
t.name,
events,
self.events.name,
)
return calls + events
async def _delete_batches(self, table: Any, ids_query: Any) -> int:
batch = ids_query.limit(self.prune_batch)
total = 0
while True:
async with self.engine.begin() as conn:
ids = (await conn.execute(batch)).scalars().all()
if ids:
await conn.execute(delete(t).where(t.c.id.in_(ids)))
await conn.execute(delete(table).where(table.c.id.in_(ids)))
total += len(ids)
if len(ids) < self.prune_batch:
return total
async def _has_table(self, name: str) -> bool:
async with self.engine.connect() as conn:
return await conn.run_sync(lambda sync: inspect(sync).has_table(name))
async def events_for(
self, key: str, *, kinds: Sequence[str] | None = None, limit: int = 1000
) -> list[dict[str, Any]]:
"""The newest ``limit`` events for ``key``, newest first."""
await self._ready()
e = self.events
query = select(e).where(e.c.key == key)
if kinds is not None:
query = query.where(e.c.kind.in_(list(kinds)))
query = query.order_by(e.c.occurred_at.desc()).limit(limit)
async with self.engine.connect() as conn:
return [dict(row) for row in (await conn.execute(query)).mappings()]
async def recent_calls(
self,
*,
+581
View File
@@ -0,0 +1,581 @@
"""Tests for events: record_event, record_llm_call, events_for and their storage.
Real FastMCP servers through fastmcp.Client, as in test_instrumentation.py.
"""
import asyncio
import contextlib
import io
import json
import threading
from datetime import UTC, datetime, timedelta
import pytest
from fastmcp import Client, FastMCP
from fastmcp.exceptions import ToolError
from sqlalchemy import MetaData, func, select
from sqlalchemy.exc import OperationalError
from fastmcp_feedback.instrumentation import (
REDACTED,
CallbackSink,
DatabaseSink,
EventRecord,
JsonLinesSink,
MemorySink,
ToolCallRecord,
build_metadata,
instrument,
)
@pytest.fixture
async def db(tmp_path):
"""DatabaseSinks whose engines are always disposed, or the process hangs."""
made = []
def factory(name="calls", **kwargs):
kwargs.setdefault("create_tables", True)
sink = DatabaseSink(f"sqlite+aiosqlite:///{tmp_path}/{name}.db", **kwargs)
made.append(sink)
return sink
yield factory
for sink in made:
await sink.engine.dispose()
def make_app(sinks=None, **kwargs):
"""A server whose tools record events through the middleware returned."""
sink = MemorySink()
app = FastMCP("events")
holder = {}
spawned = []
@app.tool
async def submit(job_id: str) -> dict:
mw = holder["mw"]
mw.record_event("job.submitted", key=job_id, attrs={"case": "wing", "nproc": 4})
return {"job_id": job_id}
@app.tool
def submit_sync(job_id: str) -> dict:
holder["mw"].record_event("job.submitted", key=job_id)
return {"job_id": job_id}
@app.tool
async def spawn(job_id: str) -> dict:
"""Start a watcher task that records after the call has returned."""
started = asyncio.Event()
async def watcher():
started.set()
await asyncio.sleep(0.05)
holder["mw"].record_event("job.started", key=job_id)
spawned.append(asyncio.get_running_loop().create_task(watcher()))
await started.wait()
return {"job_id": job_id}
@app.tool
async def chat(prompt: str) -> str:
holder["mw"].record_llm_call(
model="claude-opus-4",
provider="anthropic",
duration_ms=812.5,
input_tokens=1200,
output_tokens=90,
attrs={"cache_read_input_tokens": 1000},
)
return "ok"
@app.tool
async def chat_fails(prompt: str) -> str:
err = RuntimeError(
"upstream 401: api_key=sk-abcdefghijklmnopqrstuv " + "x" * 800
)
holder["mw"].record_llm_call(model="gpt-x", provider="openai", error=err)
raise err
@app.tool
def poll() -> dict:
return {"status": "idle"}
@app.tool
def poll_with_event() -> dict:
holder["mw"].record_event("poll.saw_job", key="j9")
return {"status": "idle"}
mw = instrument(app, sinks if sinks is not None else [sink], **kwargs)
holder["mw"] = mw
return app, sink, mw, spawned
async def call(app, mw, *calls):
async with Client(app) as client:
for tool, args in calls:
with contextlib.suppress(ToolError):
await client.call_tool(tool, args)
await mw.flush()
async def table_rows(sink, table):
async with sink.engine.connect() as conn:
return [dict(r) for r in (await conn.execute(select(table))).mappings()]
def event(kind="job.step", key="j1", minutes_ago=0, **kwargs):
return EventRecord(
kind=kind,
occurred_at=datetime.now(UTC) - timedelta(minutes=minutes_ago),
key=key,
**kwargs,
)
class TestLinking:
async def test_event_in_tool_links_to_stored_call(self, db):
store = db()
app, _, mw, _ = make_app([store])
await call(app, mw, ("submit", {"job_id": "j1"}))
[call_row] = await table_rows(store, store.table)
[ev] = await table_rows(store, store.events)
assert ev["kind"] == "job.submitted"
assert ev["call_id"] == call_row["id"]
assert ev["session_id"] == call_row["session_id"]
assert ev["call_id"] == mw.recent[-1].id
async def test_sync_tool_links_too(self):
app, sink, mw, _ = make_app()
await call(app, mw, ("submit_sync", {"job_id": "j2"}))
await asyncio.sleep(0.01)
await mw.flush()
[ev] = sink.events
[rec] = sink.calls
assert ev.call_id == rec.id
async def test_event_outside_call_has_no_call_id(self):
app, sink, mw, _ = make_app()
assert mw.record_event("job.finished", key="j1") is True
await mw.flush()
[ev] = sink.events
assert ev.call_id is None and ev.session_id is None
async def test_task_outliving_call_is_not_linked(self):
app, sink, mw, spawned = make_app()
await call(app, mw, ("spawn", {"job_id": "j3"}))
await asyncio.gather(*spawned)
await mw.flush()
[ev] = sink.events
assert ev.kind == "job.started" and ev.call_id is None
async def test_explicit_call_id_wins(self):
app, sink, mw, _ = make_app()
mw.record_event("x.y", call_id="given")
await mw.flush()
assert sink.events[0].call_id == "given"
async def test_sampled_out_call_kept_when_it_recorded_event(self):
app, sink, mw, _ = make_app(
sample_rates={"poll_with_event": 0.01, "poll": 0.01},
random=lambda: 0.99,
)
await call(app, mw, ("poll", {}), ("poll_with_event", {}))
[rec] = sink.calls
[ev] = sink.events
assert rec.tool == "poll_with_event" and rec.sample_rate is None
assert ev.call_id == rec.id
async def test_excluded_tool_events_unlinked(self):
app, sink, mw, _ = make_app(exclude_tools={"poll_with_event"})
await call(app, mw, ("poll_with_event", {}))
assert sink.calls == []
[ev] = sink.events
assert ev.call_id is None
class TestRecordEvent:
async def test_key_attrs_and_server_version_stored(self, db):
store = db()
app, _, mw, _ = make_app([store], server_version="1.2.3")
mw.record_event(
"step.finished",
key=42,
attrs={"step": "snappyHexMesh", "cells": 1200000, "mesh_ok": True},
user_sub="u1",
)
await mw.flush()
[ev] = await table_rows(store, store.events)
assert ev["key"] == "42"
assert ev["attrs"] == {
"step": "snappyHexMesh",
"cells": 1200000,
"mesh_ok": True,
}
assert ev["user_sub"] == "u1" and ev["server_version"] == "1.2.3"
async def test_attrs_redacted(self):
app, sink, mw, _ = make_app()
mw.record_event(
"job.failed",
attrs={
"token": "abc123",
"nested": {"db_password": "hunter2"},
"error_excerpt": "curl -H 'Authorization: Bearer abcdefghijklmnop'",
},
)
await mw.flush()
attrs = sink.events[0].attrs
assert attrs["token"] == REDACTED
assert attrs["nested"]["db_password"] == REDACTED
assert "abcdefghijklmnop" not in attrs["error_excerpt"]
async def test_attrs_made_json_safe(self, db):
store = db()
app, _, mw, _ = make_app([store])
when = datetime(2026, 9, 29, tzinfo=UTC)
mw.record_event(
"solver.progress",
key="j1",
attrs={"residuals": {"p": float("nan"), "U": 1e-5}, "at": when, 3: (1, 2)},
)
await mw.flush()
[ev] = await table_rows(store, store.events)
assert ev["attrs"] == {
"residuals": {"p": "nan", "U": 1e-5},
"at": when.isoformat(),
"3": [1, 2],
}
@pytest.mark.parametrize(
"kind",
["", " ", None, 5, "k" * 129],
ids=["empty", "blank", "none", "int", "long"],
)
async def test_invalid_kind_rejected(self, kind):
app, sink, mw, _ = make_app()
assert mw.record_event(kind) is False
await mw.flush()
assert sink.events == [] and list(mw.recent_events) == []
async def test_invalid_key_and_attrs_rejected(self):
app, sink, mw, _ = make_app()
assert mw.record_event("a.b", key="k" * 256) is False
assert mw.record_event("a.b", attrs=["not", "a", "dict"]) is False
await mw.flush()
assert sink.events == []
async def test_mode_off_is_noop(self):
app, sink, mw, _ = make_app(mode="off")
assert mw.record_event("job.submitted", key="j1") is False
assert mw.record_llm_call(model="m") is False
await call(app, mw, ("submit", {"job_id": "j1"}))
assert sink.records == [] and list(mw.recent_events) == []
assert mw.dispatcher.dropped == 0
async def test_queue_full_returns_false_and_counts(self):
app, sink, mw, _ = make_app(max_queue=1)
assert mw.record_event("a.one") is True
assert mw.record_event("a.two") is False
assert mw.dispatcher.dropped == 1
await mw.flush()
assert [e.kind for e in sink.events] == ["a.one"]
assert [e.kind for e in mw.recent_events] == ["a.one"]
async def test_broken_sink_never_raises(self):
def boom(records):
raise RuntimeError("sink down")
app, _, mw, _ = make_app([CallbackSink(boom)])
assert mw.record_event("a.b", key="j") is True
await mw.flush()
assert mw.dispatcher.sink_errors == 1
async def test_broken_redactor_never_raises(self):
app, sink, mw, _ = make_app()
class Broken:
def redact(self, value):
raise RuntimeError("bad pattern")
mw.redactor = Broken()
assert mw.record_event("a.b", attrs={"x": 1}) is False
class TestThreads:
async def test_record_from_thread_while_server_runs(self, db):
store = db()
app, _, mw, _ = make_app([store])
results = []
async with Client(app) as client:
await client.call_tool("submit", {"job_id": "j1"})
def watcher():
for kind in ("step.started", "job.finished"):
results.append(
mw.record_event(kind, key="j1", attrs={"case": "wing"})
)
t = threading.Thread(target=watcher)
t.start()
await asyncio.to_thread(t.join)
await asyncio.sleep(0)
await mw.flush()
assert results == [True, True]
rows = await table_rows(store, store.events)
assert sorted(r["kind"] for r in rows) == [
"job.finished",
"job.submitted",
"step.started",
]
threaded = [r for r in rows if r["kind"] != "job.submitted"]
assert all(r["call_id"] is None for r in threaded)
assert [e.kind for e in mw.recent_events] == [
"job.submitted",
"step.started",
"job.finished",
]
async def test_thread_with_its_own_loop_hands_over(self):
app, sink, mw, _ = make_app()
mw.record_event("a.first") # binds the dispatcher to this loop
out = []
t = threading.Thread(
target=lambda: out.append(asyncio.run(self._record_in_loop(mw)))
)
t.start()
await asyncio.to_thread(t.join)
await asyncio.sleep(0)
await mw.flush()
assert out == [True]
assert [e.kind for e in sink.events] == ["a.first", "a.second"]
assert mw.dispatcher._loop is asyncio.get_running_loop()
@staticmethod
async def _record_in_loop(mw):
return mw.record_event("a.second")
def test_no_loop_and_nothing_recorded_drops(self):
app, sink, mw, _ = make_app()
assert mw.record_event("job.started", key="j1") is False
assert mw.dispatcher.dropped == 1
assert list(mw.recent_events) == []
async def test_thread_before_anything_recorded_drops(self):
app, sink, mw, _ = make_app()
out = []
t = threading.Thread(target=lambda: out.append(mw.record_event("a.b")))
t.start()
await asyncio.to_thread(t.join)
assert out == [False] and mw.dispatcher.dropped == 1
class TestLlmCall:
async def test_attrs_and_linking(self, db):
store = db()
app, _, mw, _ = make_app([store])
await call(app, mw, ("chat", {"prompt": "hi"}))
[call_row] = await table_rows(store, store.table)
[ev] = await table_rows(store, store.events)
assert ev["kind"] == "llm.call" and ev["call_id"] == call_row["id"]
assert ev["attrs"] == {
"cache_read_input_tokens": 1000,
"model": "claude-opus-4",
"provider": "anthropic",
"duration_ms": 812.5,
"input_tokens": 1200,
"output_tokens": 90,
"ok": True,
}
async def test_error_redacted_truncated_and_not_ok(self):
app, sink, mw, _ = make_app(max_error_chars=100)
await call(app, mw, ("chat_fails", {"prompt": "hi"}))
[ev] = sink.events
attrs = ev.attrs
assert attrs["ok"] is False and attrs["error_type"] == "RuntimeError"
assert "sk-abcdefghijklmnopqrstuv" not in attrs["error"]
assert len(attrs["error"]) == 100
assert ev.call_id == sink.calls[0].id and sink.calls[0].outcome == "error"
async def test_named_fields_win_and_ok_explicit(self):
app, sink, mw, _ = make_app()
mw.record_llm_call(
model="m", ok=False, key="turn-1", attrs={"model": "spoofed", "round": 2}
)
await mw.flush()
[ev] = sink.events
assert ev.key == "turn-1"
assert ev.attrs == {"model": "m", "round": 2, "ok": False}
class TestSinks:
async def test_database_sink_mixed_batch(self, db):
store = db()
rec = ToolCallRecord(
tool="t",
started_at=datetime.now(UTC),
duration_ms=1.0,
ok=True,
mode="meta",
)
ev = event(call_id=rec.id, attrs={"a": 1})
await store.write([rec, ev])
assert [r["id"] for r in await table_rows(store, store.table)] == [rec.id]
[row] = await table_rows(store, store.events)
assert row["id"] == ev.id and row["call_id"] == rec.id
async def test_hand_built_event_attrs_made_json_safe(self, db):
store = db()
await store.write([event(attrs={"p": float("nan"), "q": float("-inf")})])
[row] = await table_rows(store, store.events)
assert row["attrs"] == {"p": "nan", "q": "-inf"}
async def test_database_sink_events_only_and_calls_only(self, db):
store = db()
await store.write([event()])
assert len(await table_rows(store, store.events)) == 1
assert await table_rows(store, store.table) == []
async def test_calls_stored_when_events_table_missing(self, tmp_path, db):
store = db("old", create_tables=False)
old = MetaData()
build_metadata("ffb_", old)
old.remove(old.tables["ffb_events"])
async with store.engine.begin() as conn:
await conn.run_sync(old.create_all)
rec = ToolCallRecord(
tool="t",
started_at=datetime.now(UTC),
duration_ms=1.0,
ok=True,
mode="meta",
)
with pytest.raises(OperationalError, match="no such table"):
await store.write([rec, event()])
assert len(await table_rows(store, store.table)) == 1
async def test_json_lines_record_field(self):
stream = io.StringIO()
app, _, mw, _ = make_app([JsonLinesSink(stream)])
await call(app, mw, ("submit", {"job_id": "j1"}))
lines = [json.loads(line) for line in stream.getvalue().splitlines()]
by_type = {line["record"]: line for line in lines}
assert set(by_type) == {"tool_call", "event"}
assert by_type["event"]["kind"] == "job.submitted"
assert by_type["event"]["call_id"] == by_type["tool_call"]["id"]
assert by_type["tool_call"]["tool"] == "submit"
async def test_memory_sink_calls_and_events(self):
app, sink, mw, _ = make_app()
await call(app, mw, ("submit", {"job_id": "j1"}), ("poll", {}))
assert [r.tool for r in sink.calls] == ["submit", "poll"]
assert [e.kind for e in sink.events] == ["job.submitted"]
assert len(sink.records) == 3
class TestEventsFor:
async def test_merges_database_and_memory_in_time_order(self, db):
store = db()
app, _, mw, _ = make_app([store])
# Written by another worker: only in the database.
await store.write([event("job.submitted", minutes_ago=30)])
# Recorded here and flushed: in both, returned once.
mw.record_event("step.started", key="j1")
await mw.flush()
# Recorded here, not yet written: only in memory.
pending = event("step.finished", minutes_ago=-1)
mw.recent_events.append(pending)
# Another job, and a kind filtered out below.
mw.record_event("job.submitted", key="j2")
await mw.flush()
rows = await mw.events_for("j1")
assert [r["kind"] for r in rows] == [
"job.submitted",
"step.started",
"step.finished",
]
assert all(r["occurred_at"].tzinfo is not None for r in rows)
assert rows[-1]["id"] == pending.id
assert len({r["id"] for r in rows}) == 3
steps = await mw.events_for("j1", kinds=["step.started", "step.finished"])
assert [r["kind"] for r in steps] == ["step.started", "step.finished"]
last = await mw.events_for("j1", limit=2)
assert [r["kind"] for r in last] == ["step.started", "step.finished"]
async def test_memory_only_without_database(self):
app, sink, mw, _ = make_app()
await call(app, mw, ("submit", {"job_id": "j1"}))
mw.record_event("job.finished", key="j1")
rows = await mw.events_for("j1")
assert [r["kind"] for r in rows] == ["job.submitted", "job.finished"]
assert rows[0]["call_id"] == sink.calls[0].id
async def test_database_failure_falls_back_to_memory(self, db):
store = db("nodb", create_tables=False)
app, _, mw, _ = make_app([store])
mw.recent_events.append(event("job.submitted"))
rows = await mw.events_for("j1")
assert [r["kind"] for r in rows] == ["job.submitted"]
class TestPrune:
async def test_prune_deletes_old_events_in_batches(self, db):
store = db(retention=timedelta(days=30), prune_batch=2)
old_call = ToolCallRecord(
tool="old",
started_at=datetime.now(UTC) - timedelta(days=40),
duration_ms=1.0,
ok=True,
mode="meta",
)
store._last_prune = float("inf") # keep write() from pruning first
await store.write(
[old_call]
+ [event(f"old.{i}", minutes_ago=60 * 24 * 40) for i in range(5)]
+ [event("new.one"), event("new.two", minutes_ago=60 * 24 * 29)]
)
statements = []
from sqlalchemy import event as sa_event
def count_deletes(conn, cursor, statement, *args):
if statement.lstrip().upper().startswith("DELETE FROM FFB_EVENTS"):
statements.append(statement)
sa_event.listen(
store.engine.sync_engine, "before_cursor_execute", count_deletes
)
deleted = await store.prune()
assert deleted == 6 # 1 call + 5 events
assert len(statements) == 3 # 2 + 2 + 1
kinds = sorted(r["kind"] for r in await table_rows(store, store.events))
assert kinds == ["new.one", "new.two"]
async def test_auto_prune_covers_events(self, db):
store = db(retention=timedelta(days=30))
await store.write([event("old", minutes_ago=60 * 24 * 31), event("new")])
assert [r["kind"] for r in await table_rows(store, store.events)] == ["new"]
async def test_prune_without_events_table(self, db):
store = db("legacy", create_tables=False)
old = MetaData()
build_metadata("ffb_", old)
old.remove(old.tables["ffb_events"])
async with store.engine.begin() as conn:
await conn.run_sync(old.create_all)
rec = ToolCallRecord(
tool="old",
started_at=datetime.now(UTC) - timedelta(days=40),
duration_ms=1.0,
ok=True,
mode="meta",
)
await store.write([rec])
assert await store.prune(datetime.now(UTC) - timedelta(days=30)) == 1
async with store.engine.connect() as conn:
n = (
await conn.execute(select(func.count()).select_from(store.table))
).scalar()
assert n == 0
+10 -2
View File
@@ -408,7 +408,11 @@ class TestDatabaseSink:
async with engine.connect() as conn:
tables = await conn.run_sync(lambda c: inspect(c).get_table_names())
await engine.dispose()
assert sorted(tables) == ["qa_feedback_call_links", "qa_tool_calls"]
assert sorted(tables) == [
"qa_events",
"qa_feedback_call_links",
"qa_tool_calls",
]
async def test_no_tables_created_by_default(self, tmp_path):
engine = create_async_engine(f"sqlite+aiosqlite:///{tmp_path}/host.db")
@@ -444,7 +448,11 @@ class TestDatabaseSink:
host = MetaData()
assert build_metadata("ffb_", host) is host
build_metadata("ffb_", host)
assert sorted(host.tables) == ["ffb_feedback_call_links", "ffb_tool_calls"]
assert sorted(host.tables) == [
"ffb_events",
"ffb_feedback_call_links",
"ffb_tool_calls",
]
class TestIntegration:
Generated
+1 -1
View File
@@ -553,7 +553,7 @@ wheels = [
[[package]]
name = "fastmcp-feedback"
version = "2026.9.28"
version = "2026.9.29"
source = { editable = "." }
dependencies = [
{ name = "fastmcp" },