Compare commits
3
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
99074c6fa8 | ||
|
|
d998256bc4 | ||
|
|
bf62650e05 |
@@ -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/),
|
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).
|
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
|
## [2026.09.28] - 2026-09-28
|
||||||
|
|
||||||
Keep the tool-call table small: leave out or sample busy tools, and prune old
|
Keep the tool-call table small: leave out or sample busy tools, and prune old
|
||||||
|
|||||||
@@ -185,8 +185,9 @@ instrument(app, [
|
|||||||
### Using your own database and migrations
|
### Using your own database and migrations
|
||||||
|
|
||||||
Pass the `AsyncEngine` you already have. Records go to a `ffb_tool_calls`
|
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
|
table (events to `ffb_events`; the prefix is configurable), and nothing is
|
||||||
ask. To manage the table with Alembic, add it to your `env.py`:
|
created at startup unless you ask. To manage the tables with Alembic, add them
|
||||||
|
to your `env.py`:
|
||||||
|
|
||||||
```python
|
```python
|
||||||
from fastmcp_feedback.instrumentation import build_metadata
|
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).
|
column exists, database writes fail and those records are dropped (logged).
|
||||||
Retention needs no schema change.
|
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
|
### Middleware order and shutdown
|
||||||
|
|
||||||
FastMCP runs the first middleware added as the outermost. Call `instrument()`
|
FastMCP runs the first middleware added as the outermost. Call `instrument()`
|
||||||
|
|||||||
+1
-1
@@ -4,7 +4,7 @@ build-backend = "hatchling.build"
|
|||||||
|
|
||||||
[project]
|
[project]
|
||||||
name = "fastmcp-feedback"
|
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"
|
description = "Production-ready feedback collection system for FastMCP servers"
|
||||||
readme = "README.md"
|
readme = "README.md"
|
||||||
license = "MIT"
|
license = "MIT"
|
||||||
|
|||||||
@@ -44,7 +44,7 @@ Quick Start:
|
|||||||
import logging
|
import logging
|
||||||
|
|
||||||
# Version information - CalVer YYYY.MM.DD
|
# Version information - CalVer YYYY.MM.DD
|
||||||
__version__ = "2026.09.28"
|
__version__ = "2026.09.29"
|
||||||
__author__ = "Ryan Malloy"
|
__author__ = "Ryan Malloy"
|
||||||
__email__ = "ryan@supported.systems"
|
__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) # every tool call as JSON lines on stderr
|
||||||
mw = instrument(app, [DatabaseSink(engine)], identity_resolver=who)
|
mw = instrument(app, [DatabaseSink(engine)], identity_resolver=who)
|
||||||
mw = instrument(app, result_classifier=soft_error_classifier(extra_statuses=("unknown_target",)))
|
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 (
|
from .classify import (
|
||||||
@@ -13,6 +14,7 @@ from .classify import (
|
|||||||
soft_error_classifier,
|
soft_error_classifier,
|
||||||
)
|
)
|
||||||
from .dispatch import RecordDispatcher
|
from .dispatch import RecordDispatcher
|
||||||
|
from .events import EventRecord
|
||||||
from .middleware import MODE_ENV_VAR, MODES, InstrumentationMiddleware, instrument
|
from .middleware import MODE_ENV_VAR, MODES, InstrumentationMiddleware, instrument
|
||||||
from .record import ToolCallRecord
|
from .record import ToolCallRecord
|
||||||
from .redaction import (
|
from .redaction import (
|
||||||
@@ -31,6 +33,7 @@ __all__ = [
|
|||||||
"DEFAULT_SECRET_KEYS",
|
"DEFAULT_SECRET_KEYS",
|
||||||
"DEFAULT_SECRET_PATTERNS",
|
"DEFAULT_SECRET_PATTERNS",
|
||||||
"DEFAULT_TABLE_PREFIX",
|
"DEFAULT_TABLE_PREFIX",
|
||||||
|
"EventRecord",
|
||||||
"InstrumentationMiddleware",
|
"InstrumentationMiddleware",
|
||||||
"JsonLinesSink",
|
"JsonLinesSink",
|
||||||
"MemorySink",
|
"MemorySink",
|
||||||
|
|||||||
@@ -3,10 +3,10 @@
|
|||||||
import asyncio
|
import asyncio
|
||||||
import contextlib
|
import contextlib
|
||||||
import logging
|
import logging
|
||||||
from collections.abc import Sequence
|
import threading
|
||||||
|
from collections.abc import Callable, Sequence
|
||||||
|
|
||||||
from .record import ToolCallRecord
|
from .sinks import Record, Sink
|
||||||
from .sinks import Sink
|
|
||||||
|
|
||||||
logger = logging.getLogger(__name__)
|
logger = logging.getLogger(__name__)
|
||||||
|
|
||||||
@@ -33,11 +33,13 @@ class RecordDispatcher:
|
|||||||
self.sink_timeout = sink_timeout
|
self.sink_timeout = sink_timeout
|
||||||
self.dropped = 0
|
self.dropped = 0
|
||||||
self.sink_errors = 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._task: asyncio.Task | None = None
|
||||||
self._loop: asyncio.AbstractEventLoop | 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."""
|
"""Queue a record for delivery. Returns False if it was dropped."""
|
||||||
try:
|
try:
|
||||||
loop = asyncio.get_running_loop()
|
loop = asyncio.get_running_loop()
|
||||||
@@ -45,12 +47,7 @@ class RecordDispatcher:
|
|||||||
self._drop("no running event loop")
|
self._drop("no running event loop")
|
||||||
return False
|
return False
|
||||||
|
|
||||||
# A queue belongs to one loop; tests and some hosts run several.
|
self._bind(loop)
|
||||||
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))
|
|
||||||
|
|
||||||
try:
|
try:
|
||||||
self._queue.put_nowait(record)
|
self._queue.put_nowait(record)
|
||||||
except asyncio.QueueFull:
|
except asyncio.QueueFull:
|
||||||
@@ -58,11 +55,79 @@ class RecordDispatcher:
|
|||||||
return False
|
return False
|
||||||
return True
|
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:
|
def _drop(self, reason: str) -> None:
|
||||||
self.dropped += 1
|
with self._drop_lock:
|
||||||
if self.dropped == 1 or self.dropped % 1000 == 0:
|
self.dropped += 1
|
||||||
|
dropped = self.dropped
|
||||||
|
if dropped == 1 or dropped % 1000 == 0:
|
||||||
logger.warning(
|
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:
|
async def _run(self, queue: asyncio.Queue) -> None:
|
||||||
@@ -79,7 +144,7 @@ class RecordDispatcher:
|
|||||||
for _ in batch:
|
for _ in batch:
|
||||||
queue.task_done()
|
queue.task_done()
|
||||||
|
|
||||||
async def _deliver(self, batch: list[ToolCallRecord]) -> None:
|
async def _deliver(self, batch: list[Record]) -> None:
|
||||||
for sink in self.sinks:
|
for sink in self.sinks:
|
||||||
try:
|
try:
|
||||||
await asyncio.wait_for(sink.write(batch), self.sink_timeout)
|
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 asyncio
|
||||||
|
import contextlib
|
||||||
|
import contextvars
|
||||||
import inspect
|
import inspect
|
||||||
import json
|
import json
|
||||||
import logging
|
import logging
|
||||||
@@ -25,6 +27,13 @@ from .correlation import (
|
|||||||
select_calls,
|
select_calls,
|
||||||
)
|
)
|
||||||
from .dispatch import RecordDispatcher
|
from .dispatch import RecordDispatcher
|
||||||
|
from .events import (
|
||||||
|
MAX_KEY_CHARS,
|
||||||
|
MAX_KIND_CHARS,
|
||||||
|
CallScope,
|
||||||
|
EventRecord,
|
||||||
|
jsonable,
|
||||||
|
)
|
||||||
from .record import ToolCallRecord
|
from .record import ToolCallRecord
|
||||||
from .redaction import Redactor
|
from .redaction import Redactor
|
||||||
from .sinks import JsonLinesSink, Sink
|
from .sinks import JsonLinesSink, Sink
|
||||||
@@ -150,6 +159,12 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
sampled out are not kept for correlation either.
|
sampled out are not kept for correlation either.
|
||||||
random: ``() -> float`` in [0, 1) deciding sampling; a call is kept
|
random: ``() -> float`` in [0, 1) deciding sampling; a call is kept
|
||||||
when it returns less than the tool's rate. For tests.
|
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__(
|
def __init__(
|
||||||
@@ -173,6 +188,7 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
exclude_tools: Iterable[str] = (),
|
exclude_tools: Iterable[str] = (),
|
||||||
sample_rates: Mapping[str, float] | None = None,
|
sample_rates: Mapping[str, float] | None = None,
|
||||||
random: Callable[[], float] = _random.random,
|
random: Callable[[], float] = _random.random,
|
||||||
|
recent_events: int = 2000,
|
||||||
):
|
):
|
||||||
mode = (mode or os.getenv(MODE_ENV_VAR) or "meta").lower()
|
mode = (mode or os.getenv(MODE_ENV_VAR) or "meta").lower()
|
||||||
if mode not in MODES:
|
if mode not in MODES:
|
||||||
@@ -198,6 +214,11 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
self.sample_rates[tool] = rate
|
self.sample_rates[tool] = rate
|
||||||
self.random = random
|
self.random = random
|
||||||
self.recent: deque[ToolCallRecord] = deque(maxlen=recent_calls)
|
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(
|
self.dispatcher = RecordDispatcher(
|
||||||
sinks if sinks is not None else [JsonLinesSink()],
|
sinks if sinks is not None else [JsonLinesSink()],
|
||||||
max_queue=max_queue,
|
max_queue=max_queue,
|
||||||
@@ -208,6 +229,8 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
async def on_call_tool(self, context: MiddlewareContext, call_next):
|
async def on_call_tool(self, context: MiddlewareContext, call_next):
|
||||||
if self.mode == "off":
|
if self.mode == "off":
|
||||||
return await call_next(context)
|
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:
|
if _tool_name(context) in self.exclude_tools:
|
||||||
return await call_next(context)
|
return await call_next(context)
|
||||||
|
|
||||||
@@ -215,6 +238,16 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
start = time.perf_counter()
|
start = time.perf_counter()
|
||||||
result = None
|
result = None
|
||||||
error: BaseException | None = 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:
|
try:
|
||||||
result = await call_next(context)
|
result = await call_next(context)
|
||||||
return result
|
return result
|
||||||
@@ -223,8 +256,16 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
raise
|
raise
|
||||||
finally:
|
finally:
|
||||||
duration_ms = (time.perf_counter() - start) * 1000
|
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:
|
try:
|
||||||
await self._record(context, started_at, duration_ms, result, error)
|
await self._record(
|
||||||
|
context, started_at, duration_ms, result, error, scope
|
||||||
|
)
|
||||||
except Exception:
|
except Exception:
|
||||||
logger.warning("Failed to record tool call", exc_info=True)
|
logger.warning("Failed to record tool call", exc_info=True)
|
||||||
|
|
||||||
@@ -235,6 +276,7 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
duration_ms: float,
|
duration_ms: float,
|
||||||
result: Any,
|
result: Any,
|
||||||
error: BaseException | None,
|
error: BaseException | None,
|
||||||
|
scope: CallScope | None = None,
|
||||||
) -> None:
|
) -> None:
|
||||||
tool = _tool_name(context)
|
tool = _tool_name(context)
|
||||||
payload = _result_payload(result) if result is not None else None
|
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:
|
if error is None and self.result_classifier is not None and payload is not None:
|
||||||
soft = self._classify(tool, result, payload)
|
soft = self._classify(tool, result, payload)
|
||||||
rate = self.sample_rates.get(tool)
|
rate = self.sample_rates.get(tool)
|
||||||
# Failures are always kept, and their rows carry no sample_rate.
|
# Failures are always kept, and their rows carry no sample_rate. So are
|
||||||
if rate is not None and (error is not None or soft is not None):
|
# 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
|
rate = None
|
||||||
elif rate is not None and not self.random() < rate:
|
elif rate is not None and not self.random() < rate:
|
||||||
return
|
return
|
||||||
record = await self._build_record(
|
record = await self._build_record(
|
||||||
context, started_at, duration_ms, payload, error, soft, rate
|
context, started_at, duration_ms, payload, error, soft, rate
|
||||||
)
|
)
|
||||||
|
if scope is not None:
|
||||||
|
record.id = scope.id
|
||||||
self.recent.append(record)
|
self.recent.append(record)
|
||||||
self.dispatcher.submit(record)
|
self.dispatcher.submit(record)
|
||||||
|
|
||||||
@@ -348,6 +395,144 @@ class InstrumentationMiddleware(Middleware):
|
|||||||
sample_rate=sample_rate,
|
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
|
@property
|
||||||
def database_sink(self) -> DatabaseSink | None:
|
def database_sink(self) -> DatabaseSink | None:
|
||||||
"""The first DatabaseSink among the sinks, if any."""
|
"""The first DatabaseSink among the sinks, if any."""
|
||||||
|
|||||||
@@ -3,7 +3,7 @@
|
|||||||
import uuid
|
import uuid
|
||||||
from dataclasses import asdict, dataclass, field
|
from dataclasses import asdict, dataclass, field
|
||||||
from datetime import datetime
|
from datetime import datetime
|
||||||
from typing import Any
|
from typing import Any, ClassVar
|
||||||
|
|
||||||
|
|
||||||
@dataclass
|
@dataclass
|
||||||
@@ -22,6 +22,8 @@ class ToolCallRecord:
|
|||||||
unconditionally, including failures of sampled tools.
|
unconditionally, including failures of sampled tools.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
|
record_type: ClassVar[str] = "tool_call"
|
||||||
|
|
||||||
tool: str
|
tool: str
|
||||||
started_at: datetime
|
started_at: datetime
|
||||||
duration_ms: float
|
duration_ms: float
|
||||||
|
|||||||
@@ -1,4 +1,4 @@
|
|||||||
"""Destinations for tool-call records."""
|
"""Destinations for tool-call and event records."""
|
||||||
|
|
||||||
import inspect
|
import inspect
|
||||||
import json
|
import json
|
||||||
@@ -6,27 +6,38 @@ import sys
|
|||||||
from collections.abc import Callable, Sequence
|
from collections.abc import Callable, Sequence
|
||||||
from typing import IO, Any, Protocol, runtime_checkable
|
from typing import IO, Any, Protocol, runtime_checkable
|
||||||
|
|
||||||
|
from .events import EventRecord
|
||||||
from .record import ToolCallRecord
|
from .record import ToolCallRecord
|
||||||
|
|
||||||
|
Record = ToolCallRecord | EventRecord
|
||||||
|
|
||||||
|
|
||||||
@runtime_checkable
|
@runtime_checkable
|
||||||
class Sink(Protocol):
|
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:
|
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):
|
def __init__(self, stream: IO[str] | None = None):
|
||||||
self._stream = stream
|
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.
|
# Resolved per write so a stderr swapped by the host or a test is honored.
|
||||||
stream = self._stream or sys.stderr
|
stream = self._stream or sys.stderr
|
||||||
for record in records:
|
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()
|
stream.flush()
|
||||||
|
|
||||||
|
|
||||||
@@ -36,20 +47,32 @@ class CallbackSink:
|
|||||||
A sync callback runs on the event loop, so keep it quick.
|
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
|
self.callback = callback
|
||||||
|
|
||||||
async def write(self, records: Sequence[ToolCallRecord]) -> None:
|
async def write(self, records: Sequence[Record]) -> None:
|
||||||
result = self.callback(records)
|
result = self.callback(records)
|
||||||
if inspect.isawaitable(result):
|
if inspect.isawaitable(result):
|
||||||
await result
|
await result
|
||||||
|
|
||||||
|
|
||||||
class MemorySink:
|
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):
|
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)
|
self.records.extend(records)
|
||||||
|
|||||||
@@ -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
|
Hosts that manage their own schema include ``build_metadata(prefix)`` in their
|
||||||
Alembic ``env.py`` (``target_metadata``) and pass their existing AsyncEngine to
|
Alembic ``env.py`` (``target_metadata``) and pass their existing AsyncEngine to
|
||||||
@@ -26,13 +26,16 @@ from sqlalchemy import (
|
|||||||
and_,
|
and_,
|
||||||
delete,
|
delete,
|
||||||
exists,
|
exists,
|
||||||
|
inspect,
|
||||||
or_,
|
or_,
|
||||||
select,
|
select,
|
||||||
)
|
)
|
||||||
from sqlalchemy.dialects.postgresql import JSONB
|
from sqlalchemy.dialects.postgresql import JSONB
|
||||||
from sqlalchemy.ext.asyncio import AsyncEngine, create_async_engine
|
from sqlalchemy.ext.asyncio import AsyncEngine, create_async_engine
|
||||||
|
|
||||||
|
from .events import MAX_KEY_CHARS, MAX_KIND_CHARS, EventRecord
|
||||||
from .record import ToolCallRecord
|
from .record import ToolCallRecord
|
||||||
|
from .sinks import Record
|
||||||
|
|
||||||
logger = logging.getLogger(__name__)
|
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(
|
def build_metadata(
|
||||||
prefix: str = DEFAULT_TABLE_PREFIX, metadata: MetaData | None = None
|
prefix: str = DEFAULT_TABLE_PREFIX, metadata: MetaData | None = None
|
||||||
) -> MetaData:
|
) -> 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.
|
Pass an existing MetaData to add the tables to it instead.
|
||||||
"""
|
"""
|
||||||
metadata = metadata if metadata is not None else MetaData()
|
metadata = metadata if metadata is not None else MetaData()
|
||||||
calls = f"{prefix}tool_calls"
|
calls = f"{prefix}tool_calls"
|
||||||
|
events = f"{prefix}events"
|
||||||
links = f"{prefix}feedback_call_links"
|
links = f"{prefix}feedback_call_links"
|
||||||
if calls not in metadata.tables:
|
if calls not in metadata.tables:
|
||||||
Table(
|
Table(
|
||||||
@@ -82,6 +87,24 @@ def build_metadata(
|
|||||||
# NULL for rows recorded unconditionally and before 2026.09.28.
|
# NULL for rows recorded unconditionally and before 2026.09.28.
|
||||||
Column("sample_rate", Float),
|
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:
|
if links not in metadata.tables:
|
||||||
# No foreign key to tool_calls: a link can be written before its call
|
# 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.
|
# record has left the queue, and hosts may keep calls elsewhere.
|
||||||
@@ -98,7 +121,7 @@ def build_metadata(
|
|||||||
|
|
||||||
|
|
||||||
class DatabaseSink:
|
class DatabaseSink:
|
||||||
"""Write records to ``{prefix}tool_calls`` through an async engine.
|
"""Write records to ``{prefix}tool_calls`` and ``{prefix}events``.
|
||||||
|
|
||||||
Args:
|
Args:
|
||||||
engine: an AsyncEngine the host already owns, or a URL such as
|
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.
|
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
|
create_tables: create the tables on first use. Off by default; hosts
|
||||||
with Alembic should generate a migration from ``build_metadata``.
|
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
|
runs ``prune()`` at most once per ``prune_interval``, after its
|
||||||
insert, in the background writer. None (the default) keeps rows
|
insert, in the background writer. None (the default) keeps rows
|
||||||
forever. Calls linked to feedback are never pruned.
|
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.engine = create_async_engine(engine) if isinstance(engine, str) else engine
|
||||||
self.metadata = build_metadata(prefix)
|
self.metadata = build_metadata(prefix)
|
||||||
self.table = self.metadata.tables[f"{prefix}tool_calls"]
|
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.links = self.metadata.tables[f"{prefix}feedback_call_links"]
|
||||||
self.create_tables = create_tables
|
self.create_tables = create_tables
|
||||||
self._tables_ready = False
|
self._tables_ready = False
|
||||||
@@ -159,12 +183,20 @@ class DatabaseSink:
|
|||||||
if not self._tables_ready:
|
if not self._tables_ready:
|
||||||
await self.ensure_tables()
|
await self.ensure_tables()
|
||||||
|
|
||||||
async def write(self, records: Sequence[ToolCallRecord]) -> None:
|
async def write(self, records: Sequence[Record]) -> None:
|
||||||
if not records:
|
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
|
return
|
||||||
await self._ready()
|
await self._ready()
|
||||||
async with self.engine.begin() as conn:
|
# Separate transactions, calls first: a host that has not created the
|
||||||
await conn.execute(self.table.insert(), [r.to_row() for r in records])
|
# 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()
|
await self._auto_prune()
|
||||||
|
|
||||||
async def _auto_prune(self) -> None:
|
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.
|
# Set before running, so a prune that fails is not retried every write.
|
||||||
self._last_prune = now
|
self._last_prune = now
|
||||||
try:
|
try:
|
||||||
deleted = await self.prune()
|
await self.prune()
|
||||||
if deleted:
|
|
||||||
logger.info(
|
|
||||||
"Pruned %d tool-call rows from %s", deleted, self.table.name
|
|
||||||
)
|
|
||||||
except Exception:
|
except Exception:
|
||||||
logger.warning("Pruning %s failed", self.table.name, exc_info=True)
|
logger.warning("Pruning %s failed", self.table.name, exc_info=True)
|
||||||
|
|
||||||
async def prune(self, older_than: datetime | None = None) -> int:
|
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.
|
Defaults to now minus ``retention``; with neither, deletes nothing.
|
||||||
Calls linked to feedback in ``{prefix}feedback_call_links`` are kept,
|
Calls linked to feedback in ``{prefix}feedback_call_links`` are kept,
|
||||||
and links are never deleted. Deletes ``prune_batch`` rows per
|
and links are never deleted. Events go by ``occurred_at``, whatever
|
||||||
transaction until none are left. Returns the number of rows deleted.
|
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 older_than is None:
|
||||||
if self.retention is None:
|
if self.retention is None:
|
||||||
@@ -201,24 +232,58 @@ class DatabaseSink:
|
|||||||
older_than = datetime.now(UTC) - self.retention
|
older_than = datetime.now(UTC) - self.retention
|
||||||
await self._ready()
|
await self._ready()
|
||||||
t, link = self.table, self.links
|
t, link = self.table, self.links
|
||||||
batch = (
|
calls = await self._delete_batches(
|
||||||
select(t.c.id)
|
t,
|
||||||
.where(
|
select(t.c.id).where(
|
||||||
t.c.started_at < older_than,
|
t.c.started_at < older_than,
|
||||||
~exists().where(link.c.call_id == t.c.id),
|
~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
|
total = 0
|
||||||
while True:
|
while True:
|
||||||
async with self.engine.begin() as conn:
|
async with self.engine.begin() as conn:
|
||||||
ids = (await conn.execute(batch)).scalars().all()
|
ids = (await conn.execute(batch)).scalars().all()
|
||||||
if ids:
|
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)
|
total += len(ids)
|
||||||
if len(ids) < self.prune_batch:
|
if len(ids) < self.prune_batch:
|
||||||
return total
|
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(
|
async def recent_calls(
|
||||||
self,
|
self,
|
||||||
*,
|
*,
|
||||||
|
|||||||
@@ -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
|
||||||
@@ -408,7 +408,11 @@ class TestDatabaseSink:
|
|||||||
async with engine.connect() as conn:
|
async with engine.connect() as conn:
|
||||||
tables = await conn.run_sync(lambda c: inspect(c).get_table_names())
|
tables = await conn.run_sync(lambda c: inspect(c).get_table_names())
|
||||||
await engine.dispose()
|
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):
|
async def test_no_tables_created_by_default(self, tmp_path):
|
||||||
engine = create_async_engine(f"sqlite+aiosqlite:///{tmp_path}/host.db")
|
engine = create_async_engine(f"sqlite+aiosqlite:///{tmp_path}/host.db")
|
||||||
@@ -444,7 +448,11 @@ class TestDatabaseSink:
|
|||||||
host = MetaData()
|
host = MetaData()
|
||||||
assert build_metadata("ffb_", host) is host
|
assert build_metadata("ffb_", host) is host
|
||||||
build_metadata("ffb_", 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:
|
class TestIntegration:
|
||||||
|
|||||||
@@ -553,7 +553,7 @@ wheels = [
|
|||||||
|
|
||||||
[[package]]
|
[[package]]
|
||||||
name = "fastmcp-feedback"
|
name = "fastmcp-feedback"
|
||||||
version = "2026.9.28"
|
version = "2026.9.29"
|
||||||
source = { editable = "." }
|
source = { editable = "." }
|
||||||
dependencies = [
|
dependencies = [
|
||||||
{ name = "fastmcp" },
|
{ name = "fastmcp" },
|
||||||
|
|||||||
Reference in New Issue
Block a user