perf(ai-chat): формат трейса tool_calls v2 — outputs только в parts (#490)
Каждый tool-output хранился ДВАЖДЫ: в metadata.parts (assistantParts) И в
tool_calls (serializeSteps). При 50-шаговом ране с outputs по 50–200 KB это
127–510 МБ записи в Postgres за ход (+WAL/TOAST/dead tuples), т.к. onStepFinish
переписывает всю строку. Копия в parts — та, что реально реплеится модели и
рендерится UI/markdown-экспортом, так что копия в трейсе была чистым дублем.
Новый формат элементов tool_calls (v2), парно на каждый вызов:
{toolName, input} — вызов
{toolName, ok: true} — успех (БЕЗ output)
{toolName, error, kind: 'thrown'} — брошенный tool-error
{toolName, error, kind: 'interrupted'} — прерван mid-step (abort/restart)
kind обязателен: синтетический «Tool call did not complete.» при прерывании иначе
неотличим от реального hard-fail и загрязняет error-rate. Различие структурное
(errorsById-хит против синтетической ветки), НЕ per-tool классификатор — soft-
маркеры в трейс не выносятся (остаются в metadata.parts).
metadata.toolTraceVersion: 2 — маркер эры; старые строки НЕ мигрируются
(перезапись гигантских jsonb — тот самый WAL-чарн). serializeSteps пейрит
результаты/ошибки по toolCallId (как assistantParts); общая константа
TOOL_CALL_INCOMPLETE_TEXT держит текст реплея и трейса в синхроне.
docs/reading-ai-logs.md переписан dual-shape: ветвление по toolTraceVersion,
soft-анализ v2 через metadata.parts, правило «не сравнивать агрегаты через границу
эр». UI action-log и markdown-экспорт читают только parts — не затронуты.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -231,61 +231,137 @@ describe('assistantParts', () => {
|
||||
});
|
||||
});
|
||||
|
||||
describe('serializeSteps', () => {
|
||||
// #490 trace format v2: per call the trace stores { input } for the call and an
|
||||
// OUTCOME element — { ok: true } on success, { error, kind: 'thrown' } on a
|
||||
// thrown tool-error, { error, kind: 'interrupted' } on a mid-step abort. The tool
|
||||
// OUTPUT is no longer duplicated here (it lives once in metadata.parts).
|
||||
describe('serializeSteps (trace v2)', () => {
|
||||
it('returns null when there are no calls or results', () => {
|
||||
expect(serializeSteps([])).toBeNull();
|
||||
});
|
||||
|
||||
it('flattens calls and results into a compact trace', () => {
|
||||
it('pairs a successful call with an { ok: true } outcome and NO output', () => {
|
||||
const trace = serializeSteps([
|
||||
{
|
||||
toolCalls: [{ toolName: 'getPage', input: { id: 'p1' } }],
|
||||
toolResults: [{ toolName: 'getPage', output: { title: 'T' } }],
|
||||
toolCalls: [{ toolCallId: 'c1', toolName: 'getPage', input: { id: 'p1' } }],
|
||||
toolResults: [{ toolCallId: 'c1', toolName: 'getPage' }],
|
||||
},
|
||||
]) as Array<Record<string, unknown>>;
|
||||
expect(trace).toHaveLength(2);
|
||||
expect(trace[0]).toEqual({ toolName: 'getPage', input: { id: 'p1' } });
|
||||
expect(trace[1]).toEqual({ toolName: 'getPage', output: { title: 'T' } });
|
||||
expect(trace[1]).toEqual({ toolName: 'getPage', ok: true });
|
||||
// The output is NOT stored in the trace any more (dedup: it lives in parts).
|
||||
expect(trace.some((e) => 'output' in e)).toBe(false);
|
||||
});
|
||||
|
||||
it('records a THROWN tool failure (tool-error part) with its error message', () => {
|
||||
it('records a THROWN failure with { error, kind: "thrown" }', () => {
|
||||
const trace = serializeSteps([
|
||||
{
|
||||
toolCalls: [{ toolName: 'editPageText', input: { id: 'p1' } }],
|
||||
toolCalls: [
|
||||
{ toolCallId: 'c1', toolName: 'editPageText', input: { id: 'p1' } },
|
||||
],
|
||||
toolResults: [],
|
||||
content: [
|
||||
{
|
||||
type: 'tool-error',
|
||||
toolCallId: 'c1',
|
||||
toolName: 'editPageText',
|
||||
error: new Error('page is locked'),
|
||||
},
|
||||
],
|
||||
},
|
||||
]) as Array<Record<string, unknown>>;
|
||||
// The call element is followed by a paired error element (mirroring how a
|
||||
// successful result is appended), so the failure survives in the trace.
|
||||
expect(trace).toHaveLength(2);
|
||||
expect(trace[0]).toEqual({ toolName: 'editPageText', input: { id: 'p1' } });
|
||||
expect(trace[1]).toEqual({
|
||||
toolName: 'editPageText',
|
||||
error: 'page is locked',
|
||||
kind: 'thrown',
|
||||
});
|
||||
});
|
||||
|
||||
it('truncates a very long tool-error message to the tool-output limit', () => {
|
||||
it('marks an interrupted call (no result, no throw) with kind "interrupted"', () => {
|
||||
const trace = serializeSteps([
|
||||
{
|
||||
toolCalls: [
|
||||
{ toolCallId: 'c1', toolName: 'createComment', input: { x: 1 } },
|
||||
],
|
||||
toolResults: [],
|
||||
content: [],
|
||||
},
|
||||
]) as Array<Record<string, unknown>>;
|
||||
expect(trace).toHaveLength(2);
|
||||
expect(trace[1]).toEqual({
|
||||
toolName: 'createComment',
|
||||
error: 'Tool call did not complete.',
|
||||
kind: 'interrupted',
|
||||
});
|
||||
// Structurally distinct from a thrown hard-fail so it never inflates an
|
||||
// error-rate scan.
|
||||
expect((trace[1] as { kind: string }).kind).not.toBe('thrown');
|
||||
});
|
||||
|
||||
it('truncates a very long thrown-error message to the tool-output limit', () => {
|
||||
const long = 'x'.repeat(5000);
|
||||
const trace = serializeSteps([
|
||||
{
|
||||
toolCalls: [{ toolName: 'editPageText', input: {} }],
|
||||
toolCalls: [{ toolCallId: 'c1', toolName: 'editPageText', input: {} }],
|
||||
toolResults: [],
|
||||
content: [{ type: 'tool-error', toolName: 'editPageText', error: long }],
|
||||
content: [
|
||||
{
|
||||
type: 'tool-error',
|
||||
toolCallId: 'c1',
|
||||
toolName: 'editPageText',
|
||||
error: long,
|
||||
},
|
||||
],
|
||||
},
|
||||
]) as Array<Record<string, unknown>>;
|
||||
const errorText = trace[1].error as string;
|
||||
// Truncated (not the full 5000 chars) and carries the omission marker.
|
||||
expect(errorText.length).toBeLessThan(long.length);
|
||||
expect(errorText).toContain('chars omitted');
|
||||
});
|
||||
|
||||
it('pairs parallel calls in one step with their outcomes by id', () => {
|
||||
const trace = serializeSteps([
|
||||
{
|
||||
toolCalls: [
|
||||
{ toolCallId: 'a', toolName: 'getPage', input: {} },
|
||||
{ toolCallId: 'b', toolName: 'searchPages', input: {} },
|
||||
],
|
||||
toolResults: [{ toolCallId: 'b', toolName: 'searchPages' }],
|
||||
content: [
|
||||
{ type: 'tool-error', toolCallId: 'a', toolName: 'getPage', error: 'nope' },
|
||||
],
|
||||
},
|
||||
]) as Array<Record<string, unknown>>;
|
||||
// call a, outcome a (thrown), call b, outcome b (ok)
|
||||
expect(trace).toHaveLength(4);
|
||||
expect(trace[1]).toEqual({ toolName: 'getPage', error: 'nope', kind: 'thrown' });
|
||||
expect(trace[3]).toEqual({ toolName: 'searchPages', ok: true });
|
||||
});
|
||||
});
|
||||
|
||||
// #490: every assistant row flushAssistant writes carries the v2 era marker so a
|
||||
// dual-shape diagnostic query can branch on the trace shape without inspecting it.
|
||||
describe('toolTraceVersion era marker (#490)', () => {
|
||||
it('stamps metadata.toolTraceVersion = 2 on every flushed row', () => {
|
||||
const seed = flushAssistant([], '', 'streaming');
|
||||
expect(seed.metadata.toolTraceVersion).toBe(2);
|
||||
const done = flushAssistant(
|
||||
[
|
||||
{
|
||||
text: 'ok',
|
||||
toolCalls: [{ toolCallId: 'c1', toolName: 'getPage', input: {} }],
|
||||
toolResults: [{ toolCallId: 'c1', toolName: 'getPage' }],
|
||||
},
|
||||
],
|
||||
'',
|
||||
'completed',
|
||||
{ finishReason: 'stop' },
|
||||
);
|
||||
expect(done.metadata.toolTraceVersion).toBe(2);
|
||||
});
|
||||
});
|
||||
|
||||
describe('rowToUiMessage', () => {
|
||||
|
||||
@@ -2152,6 +2152,15 @@ export function sanitizeUserParts(
|
||||
/** Marker for a history row whose tool parts could not be replayed (#489). */
|
||||
export const TOOL_CONTEXT_OMITTED_MARKER = '[tool context omitted]';
|
||||
|
||||
/**
|
||||
* Synthetic error text for a tool call that neither returned a result nor threw
|
||||
* a `tool-error` — i.e. it was interrupted mid-step (an abort / server restart).
|
||||
* Shared by `assistantParts` (the replayed `output-error` part) and
|
||||
* `serializeSteps` (the `{ kind: 'interrupted' }` trace element) so the replay
|
||||
* text and the trace stay in lockstep (#490).
|
||||
*/
|
||||
export const TOOL_CALL_INCOMPLETE_TEXT = 'Tool call did not complete.';
|
||||
|
||||
/**
|
||||
* Convert persisted UI history to model messages, tolerating a single poisoned
|
||||
* row (#489). `convertToModelMessages` over the WHOLE array throws if ANY row is
|
||||
@@ -2419,7 +2428,7 @@ export function assistantParts(
|
||||
toolCallId: call.toolCallId,
|
||||
state: 'output-error',
|
||||
input: call.input,
|
||||
errorText: 'Tool call did not complete.',
|
||||
errorText: TOOL_CALL_INCOMPLETE_TEXT,
|
||||
});
|
||||
}
|
||||
}
|
||||
@@ -2602,6 +2611,11 @@ export function flushAssistant(
|
||||
|
||||
const metadata: Record<string, unknown> = {
|
||||
parts: parts as unknown as UIMessage['parts'],
|
||||
// Era marker for the `tool_calls` trace shape (#490): v2 stores outcome flags
|
||||
// ({ ok } / { error, kind }) and NO tool output (the output lives once in
|
||||
// `parts`). Old rows have no marker and the legacy { output } shape; a
|
||||
// dual-shape query branches on this. Old rows are deliberately NOT migrated.
|
||||
toolTraceVersion: 2,
|
||||
};
|
||||
// finishReason: prefer an explicit one; else derive a sensible value from the
|
||||
// terminal status (so onError/onAbort records keep their historical reason).
|
||||
@@ -2642,42 +2656,85 @@ export function flushAssistant(
|
||||
|
||||
/**
|
||||
* Reduce SDK step objects to a compact, JSON-serializable trace for the
|
||||
* `tool_calls` column. Stores only what the UI action-log and history need —
|
||||
* never raw provider payloads or keys.
|
||||
* `tool_calls` column — trace format **v2** (#490).
|
||||
*
|
||||
* v2 stores, per call, ONLY the metadata a queryable trace needs — never the
|
||||
* tool OUTPUT. Before #490 each output was persisted TWICE: once here (compacted)
|
||||
* and once in `metadata.parts` (via `assistantParts`), so a 50-step run with
|
||||
* 50–200 KB outputs wrote hundreds of MB per turn (each `onStepFinish` rewrote
|
||||
* the whole row). The parts copy is the one the model replays and the UI/Markdown
|
||||
* export render, so the trace copy of the output was pure duplication. v2 keeps
|
||||
* the output ONLY in parts and reduces the trace to outcome flags.
|
||||
*
|
||||
* Element shapes (paired per call, in order):
|
||||
* - `{ toolName, input }` — the call
|
||||
* - `{ toolName, ok: true }` — it returned a result (success)
|
||||
* - `{ toolName, error, kind: 'thrown' }` — it threw a `tool-error`
|
||||
* - `{ toolName, error, kind: 'interrupted' }` — no result and no throw (an
|
||||
* abort / server restart mid-step). `kind` is MANDATORY: without it a
|
||||
* synthetic "Tool call did not complete." is indistinguishable from a real
|
||||
* hard-fail and pollutes any error-rate scan. The distinction is STRUCTURAL
|
||||
* (an `errorsById` hit vs the synthetic fallback branch), NOT a per-tool
|
||||
* classifier — soft failures stay OUT of the trace (they live in
|
||||
* `metadata.parts` outputs; a per-tool mirror would persist its own bugs).
|
||||
*
|
||||
* Rows carry `metadata.toolTraceVersion: 2` (set by {@link flushAssistant}) so a
|
||||
* dual-shape query can branch on the era. Old rows are NOT migrated (rewriting
|
||||
* giant jsonb is the very WAL churn this removes); see docs/reading-ai-logs.md.
|
||||
*/
|
||||
export function serializeSteps(
|
||||
steps: ReadonlyArray<{
|
||||
toolCalls?: ReadonlyArray<{ toolName?: string; input?: unknown }>;
|
||||
toolResults?: ReadonlyArray<{ toolName?: string; output?: unknown }>;
|
||||
toolCalls?: ReadonlyArray<{
|
||||
toolCallId?: string;
|
||||
toolName?: string;
|
||||
input?: unknown;
|
||||
}>;
|
||||
toolResults?: ReadonlyArray<{ toolCallId?: string; toolName?: string }>;
|
||||
content?: ReadonlyArray<{
|
||||
type?: string;
|
||||
toolCallId?: string;
|
||||
toolName?: string;
|
||||
error?: unknown;
|
||||
}>;
|
||||
}>,
|
||||
): unknown {
|
||||
const calls: Array<{
|
||||
toolName?: string;
|
||||
input?: unknown;
|
||||
output?: unknown;
|
||||
error?: string;
|
||||
}> = [];
|
||||
const calls: Array<
|
||||
| { toolName?: string; input?: unknown }
|
||||
| { toolName?: string; ok: true }
|
||||
| { toolName?: string; error: string; kind: 'thrown' | 'interrupted' }
|
||||
> = [];
|
||||
for (const step of steps ?? []) {
|
||||
// Index this step's results + thrown errors by tool call id, so each call is
|
||||
// paired with its outcome (mirrors assistantParts' pairing exactly).
|
||||
const resultIds = new Set<string>();
|
||||
for (const r of step.toolResults ?? []) {
|
||||
if (r.toolCallId) resultIds.add(r.toolCallId);
|
||||
}
|
||||
const errorsById = new Map<string, unknown>();
|
||||
for (const part of step.content ?? []) {
|
||||
if (part.type === 'tool-error' && part.toolCallId) {
|
||||
errorsById.set(part.toolCallId, part.error);
|
||||
}
|
||||
}
|
||||
for (const call of step.toolCalls ?? []) {
|
||||
calls.push({ toolName: call.toolName, input: call.input });
|
||||
}
|
||||
for (const r of step.toolResults ?? []) {
|
||||
calls.push({ toolName: r.toolName, output: compactToolOutput(r.output) });
|
||||
}
|
||||
// ai@6 surfaces a THROWN tool failure as a `tool-error` content part, NOT as
|
||||
// a `toolResults` entry. Record it as its own paired element (mirroring how a
|
||||
// successful result is appended) so the failure and its reason survive in the
|
||||
// trace instead of leaving an orphaned call with no result.
|
||||
for (const part of step.content ?? []) {
|
||||
if (part.type === 'tool-error') {
|
||||
if (call.toolCallId && resultIds.has(call.toolCallId)) {
|
||||
// Success: the output itself lives in metadata.parts, not here.
|
||||
calls.push({ toolName: call.toolName, ok: true });
|
||||
} else if (call.toolCallId && errorsById.has(call.toolCallId)) {
|
||||
// Hard fail: the tool threw. Persist the real (bounded) reason.
|
||||
calls.push({
|
||||
toolName: part.toolName,
|
||||
error: normalizeToolError(part.error),
|
||||
toolName: call.toolName,
|
||||
error: normalizeToolError(errorsById.get(call.toolCallId)),
|
||||
kind: 'thrown',
|
||||
});
|
||||
} else {
|
||||
// Neither a result nor a throw: interrupted mid-step (abort/restart).
|
||||
// Marked structurally so it never inflates a thrown-error count.
|
||||
calls.push({
|
||||
toolName: call.toolName,
|
||||
error: TOOL_CALL_INCOMPLETE_TEXT,
|
||||
kind: 'interrupted',
|
||||
});
|
||||
}
|
||||
}
|
||||
|
||||
+174
-78
@@ -8,19 +8,35 @@ real pain (a "which tools fail most?" analysis that confidently answered
|
||||
|
||||
Read the **Gotchas** section before you trust any error count.
|
||||
|
||||
> **TWO ERAS — check the marker first.** The `tool_calls` shape changed in **#490
|
||||
> (trace v2)**. A row written by v2 carries `metadata.toolTraceVersion = 2`; older
|
||||
> rows have no such key. The two shapes store DIFFERENT things (v2 dropped the tool
|
||||
> OUTPUT from the trace), so **every query below is dual-shape** — branch on the
|
||||
> marker. **Never compare an aggregate or trend across the era boundary**: a metric
|
||||
> jump on the cut-over week is an artifact of the shape change, not a behavior
|
||||
> change.
|
||||
|
||||
## TL;DR
|
||||
|
||||
- Agent chats live in Postgres, DB `docmost`, tables `ai_chat_*`.
|
||||
- Each tool invocation is stored as **two** array elements (a `tool-call` part and
|
||||
a `tool-result` part), so naive counting double-counts.
|
||||
- **A tool that *throws* writes no result part.** Since the #407 fix its error is
|
||||
persisted as a dedicated `{toolName, error}` element in `tool_calls` (queryable +
|
||||
replayed to the model). **Rows written before #407 still drop it** — the error is
|
||||
nowhere in the DB and shows only in the live UI. So `isError` / `success=false`
|
||||
scans under-report by design, and pre-#407 thrown errors are invisible.
|
||||
- To find where agents fail: (1) soft-failure markers in `tool_calls`, (2) the new
|
||||
`error` field for thrown errors (new rows) / the orphan-gap proxy (old rows),
|
||||
(3) server logs / the live UI for full stack traces beyond the truncated message.
|
||||
- **Era marker:** `metadata.toolTraceVersion = 2` ⇒ v2 (#490) row; absent ⇒ legacy row.
|
||||
- Each tool invocation is stored as **two** consecutive array elements — a
|
||||
`tool-call` part then an OUTCOME part — so naive counting double-counts.
|
||||
- **v2 (#490):** outcome is `{toolName, ok: true}` on success, or
|
||||
`{toolName, error, kind: 'thrown'|'interrupted'}` on failure. The tool **OUTPUT
|
||||
is NOT in `tool_calls`** any more — it lives once in `metadata.parts` (this
|
||||
removed a hundreds-of-MB-per-run write duplication). Soft-failure analysis
|
||||
therefore reads `metadata.parts`, not `tool_calls`.
|
||||
- **legacy:** outcome is `{toolName, output}` on success; a **thrown** failure is
|
||||
a `{toolName, error}` element **only on rows after #407**, and is dropped
|
||||
entirely (silent orphan) on pre-#407 rows.
|
||||
- **A tool that *throws* writes no result part.** In v2 it is a
|
||||
`{error, kind:'thrown'}` element; an interrupted/aborted call is a distinct
|
||||
`{error, kind:'interrupted'}`. `isError`/`success=false` scans read the *output*
|
||||
and so under-report thrown failures in every era.
|
||||
- To find where agents fail: (1) soft-failure markers in `metadata.parts` outputs
|
||||
(v2) / `tool_calls` outputs (legacy), (2) the `error`/`kind` fields for thrown
|
||||
failures (v2 + post-#407), (3) server logs / the live UI for full stack traces.
|
||||
|
||||
## Where the data lives
|
||||
|
||||
@@ -53,33 +69,67 @@ are rows in `workspaces`, not separate deployments.
|
||||
separate `tool` role), `content` (text), `tool_calls` (jsonb array), `metadata`
|
||||
(jsonb, holds run `error` + rendered `parts`), `status`, `tsv` (full-text index).
|
||||
|
||||
## Era marker — check this before every query
|
||||
|
||||
```sql
|
||||
-- how many rows are in each era?
|
||||
SELECT COALESCE((metadata->>'toolTraceVersion'), 'legacy') AS era, count(*)
|
||||
FROM ai_chat_messages
|
||||
WHERE role = 'assistant' AND jsonb_typeof(tool_calls) = 'array'
|
||||
GROUP BY 1 ORDER BY 2 DESC;
|
||||
```
|
||||
|
||||
- `toolTraceVersion = '2'` → **v2** (#490): outcome flags, **no output in the trace**.
|
||||
- `NULL` (`'legacy'`) → pre-#490: outcome carries the tool `output` inline.
|
||||
|
||||
**Do not trend a metric across the cut-over.** The shape change alone shifts counts
|
||||
(e.g. "elements with `output`" collapses to zero for v2), so a week that straddles
|
||||
the boundary shows an artifact, not a behavior change. Segment by era, or restrict to
|
||||
one era, before comparing.
|
||||
|
||||
## How tool calls are stored — READ THIS
|
||||
|
||||
Tool calls are **not** one-object-per-call. Each logical invocation is split into
|
||||
two consecutive elements of the `tool_calls` array:
|
||||
two consecutive elements of the `tool_calls` array — a **call** then an **outcome**.
|
||||
The outcome shape is era-dependent:
|
||||
|
||||
```text
|
||||
index 0: { "toolName": "getPage", "input": { "pageId": "…" } } ← tool-call (has input, NO output)
|
||||
index 1: { "toolName": "getPage", "output": { … } } ← tool-result (has output, NO input)
|
||||
# v2 (#490) — metadata.toolTraceVersion = 2
|
||||
index 0: { "toolName":"getPage", "input":{...} } ← call (has input)
|
||||
index 1: { "toolName":"getPage", "ok":true } ← success (NO output here)
|
||||
or : { "toolName":"getPage", "error":"…", "kind":"thrown" } ← threw
|
||||
or : { "toolName":"getPage", "error":"…", "kind":"interrupted" } ← aborted mid-step
|
||||
|
||||
# legacy — no toolTraceVersion
|
||||
index 0: { "toolName":"getPage", "input":{...} } ← call (has input, NO output)
|
||||
index 1: { "toolName":"getPage", "output":{...} } ← success (has output)
|
||||
or : { "toolName":"getPage", "error":"…" } ← threw (post-#407 only)
|
||||
```
|
||||
|
||||
The keys that appear on an element are `toolName`, `input`, `output`, and — for a
|
||||
**thrown** failure on rows written after the #407 fix — `error` (the tool's error
|
||||
message; see the "Hard failures" section below). There is no `state`, no `errorText`,
|
||||
no `type`. On pre-#407 rows a thrown failure has NO paired result element at all
|
||||
(silent orphan). Consequences:
|
||||
The keys that can appear: `toolName`, `input` (call), and on the outcome — **v2:**
|
||||
`ok` **or** `error`+`kind`; **legacy:** `output` **or** (post-#407) `error`. There is
|
||||
no `state`, no `errorText`, no `type` in `tool_calls` (those live on `metadata.parts`).
|
||||
Consequences:
|
||||
|
||||
1. **Real invocation count = elements that have `output` or `error`.** Counting every
|
||||
element double-counts (you get ~2× and a spurious "~50% of every tool has no output").
|
||||
2. **Pairing:** a call = a `tool-call` part followed by its result part. A success
|
||||
carries `output`; a thrown failure (post-#407) carries `error` instead. Both carry
|
||||
`toolName`, so you can group by tool on either.
|
||||
1. **Real invocation count** — count the OUTCOME elements, not every element (else you
|
||||
double-count): **v2** = elements with `ok` or `error`; **legacy** = elements with
|
||||
`output` or `error`.
|
||||
2. **Pairing:** a call (`input`) is followed by its outcome. `toolName` is on both, so
|
||||
you can group by tool on either. In v2 the `kind` field separates a real hard-fail
|
||||
(`thrown`) from an aborted call (`interrupted`) — a distinction legacy rows cannot
|
||||
make (both are orphans; see below).
|
||||
3. **The tool OUTPUT is only in `metadata.parts` on v2 rows.** To inspect what a tool
|
||||
returned (soft-error markers, page bodies) on a v2 row, read the parts
|
||||
(`part->>'type' LIKE 'tool-%'`, `part->>'state' = 'output-available'`, `part->'output'`),
|
||||
not `tool_calls`.
|
||||
|
||||
## The two classes of failure (and which the DB can see)
|
||||
|
||||
### 1. Soft failures — tool RAN and returned an error-shaped result → PERSISTED ✅
|
||||
|
||||
These are visible in the `tool-result` `output`. The marker differs per tool:
|
||||
These are visible in the tool `output` — **on v2 rows in `metadata.parts`** (the
|
||||
`output-available` part's `output`), on **legacy rows in the `tool_calls` outcome
|
||||
element's `output`**. The marker differs per tool:
|
||||
|
||||
| Tool(s) | Error marker in `output` |
|
||||
| --- | --- |
|
||||
@@ -91,37 +141,32 @@ These are visible in the `tool-result` `output`. The marker differs per tool:
|
||||
Note `editPageText` returns `failed: []` on success — filtering on the *presence*
|
||||
of the key gives false positives; filter on **non-empty**.
|
||||
|
||||
### 2. Hard failures — tool THREW → NOW PERSISTED ✅ (since the #407 fix)
|
||||
### 2. Hard failures — tool THREW → PERSISTED ✅
|
||||
|
||||
When a tool throws (the classic one is `patchNode` / `insertNode` / `tableUpdateCell`
|
||||
→ `Failed to encode document to Yjs (fromJSON): Unknown node type: undefined`), the
|
||||
runtime still writes **no `tool-result` part** — the failure is an ai@6 `tool-error`
|
||||
content part instead. **Since the #407 fix, that error is persisted**: `serializeSteps`
|
||||
appends a dedicated element `{toolName, error: "<message>"}` right after the failed
|
||||
call, mirroring how a successful `{toolName, output}` element is appended. So a thrown
|
||||
error now leaves a queryable `error` field carrying its (truncated) reason, and the
|
||||
same real text is replayed to the model on the next turn (an `output-error` part with
|
||||
the real `errorText`, no longer the `'Tool call did not complete.'` placeholder).
|
||||
runtime writes **no `tool-result` part** — the failure is an ai@6 `tool-error` content
|
||||
part. How that lands in `tool_calls` depends on the era:
|
||||
|
||||
**Cutover caveat — old rows keep the old blind shape.** Rows written **before** this
|
||||
change have the two-part shape (`call` + `output` only) and simply **drop** thrown
|
||||
errors, leaving a silent **orphan** (a `call` with no `output` *and* no `error`). Rows
|
||||
written **after** the fix additionally carry the `error` element. So:
|
||||
- **v2 (#490):** a `{toolName, error, kind:'thrown'}` outcome element. An interrupted /
|
||||
aborted mid-step call is a **distinct** `{toolName, error:'Tool call did not
|
||||
complete.', kind:'interrupted'}` element — so you can tell a real hard-fail from an
|
||||
abort **directly, without the orphan heuristic**. Query `kind = 'thrown'`.
|
||||
- **post-#407 legacy:** a `{toolName, error}` element (no `kind`) right after the call.
|
||||
- **pre-#407 legacy:** the error is **dropped** — a silent **orphan** (a `call` with no
|
||||
`output` *and* no `error`).
|
||||
|
||||
- **New rows:** query the `error` field directly (see the hard-error query below) — no
|
||||
orphan heuristic needed for thrown failures.
|
||||
- **Old rows (pre-#407):** the only DB-side proxy is still an **orphan**: a `tool-call`
|
||||
part with no matching `tool-result` *and* no `error`. Orphans also appear when a run
|
||||
is **aborted** mid-flight (server restart), so a high-volume tool (`createComment`,
|
||||
`searchInPage`, `Search_web_search`) shows orphans from aborts, not real errors on
|
||||
old rows. Treat the orphan gap as an *upper bound*, and cross-check the tool: a gap on
|
||||
a structural editor (`patchNode`, `insertNode`, `updatePageJson`, `transformPage`) is
|
||||
almost certainly a thrown Yjs-encode error; a gap on `createComment` is mostly aborts.
|
||||
The same real error text is replayed to the model on the next turn (an `output-error`
|
||||
part with the real `errorText`, from `metadata.parts`), in every era.
|
||||
|
||||
A note on the aborted-call fallback: a call with **neither** a result **nor** a
|
||||
`tool-error` (genuinely interrupted mid-step) still replays with the
|
||||
`'Tool call did not complete.'` placeholder and persists as an orphan — that path is
|
||||
unchanged, and is distinct from a real thrown error, which now carries `error`.
|
||||
**Cutover caveat.** Only pre-#407 legacy rows need the orphan proxy: an orphan is a
|
||||
`tool-call` with no matching outcome. Orphans there also appear when a run is **aborted**
|
||||
mid-flight (server restart), so a high-volume tool (`createComment`, `searchInPage`,
|
||||
`Search_web_search`) shows orphans from aborts, not real errors. Treat the orphan gap as
|
||||
an *upper bound* and cross-check the tool: a gap on a structural editor (`patchNode`,
|
||||
`insertNode`, `updatePageJson`, `transformPage`) is almost certainly a thrown Yjs-encode
|
||||
error; a gap on `createComment` is mostly aborts. **On v2 rows this ambiguity is gone**
|
||||
— `kind` labels each outcome.
|
||||
|
||||
### 3. Run-level failures → `ai_chat_runs`
|
||||
|
||||
@@ -134,22 +179,34 @@ the wild: `Run interrupted by a server restart.` (aborts) and
|
||||
|
||||
Run all of these via `docker exec gitmost-postgresql psql -U docmost -d docmost -P pager=off -c "…"`.
|
||||
|
||||
**Real invocation count per tool** (result parts only — the correct denominator):
|
||||
**Real invocation count per tool** (outcome parts only — the correct denominator).
|
||||
Dual-shape: a v2 outcome has `ok` or `error`; a legacy outcome has `output` or `error`:
|
||||
|
||||
```sql
|
||||
SELECT elem->>'toolName' AS tool, count(*) AS calls
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array' AND elem ? 'output'
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array'
|
||||
AND (elem ? 'ok' OR elem ? 'output' OR elem ? 'error')
|
||||
GROUP BY 1 ORDER BY 2 DESC;
|
||||
```
|
||||
|
||||
**Soft errors per tool** (everything the DB can honestly see):
|
||||
**Soft errors per tool.** The soft-error marker lives in the tool OUTPUT — which on
|
||||
**v2 rows is in `metadata.parts`**, on **legacy rows is in the `tool_calls` outcome
|
||||
element**. This query UNIONs both eras, projecting each output as `o`:
|
||||
|
||||
```sql
|
||||
WITH res AS (
|
||||
-- v2 (#490): output is in metadata.parts (output-available tool parts)
|
||||
SELECT part->>'type' AS tool, part->'output' AS o
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.metadata->'parts') part
|
||||
WHERE (m.metadata->>'toolTraceVersion') = '2'
|
||||
AND part->>'type' LIKE 'tool-%' AND part->>'state' = 'output-available'
|
||||
UNION ALL
|
||||
-- legacy: output is inline in the tool_calls outcome element
|
||||
SELECT elem->>'toolName' AS tool, elem->'output' AS o
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array' AND elem ? 'output'
|
||||
WHERE (m.metadata->>'toolTraceVersion') IS NULL
|
||||
AND jsonb_typeof(m.tool_calls) = 'array' AND elem ? 'output'
|
||||
)
|
||||
SELECT tool, count(*) AS calls,
|
||||
sum(COALESCE(
|
||||
@@ -167,13 +224,23 @@ FROM res GROUP BY tool HAVING sum(COALESCE(
|
||||
ORDER BY soft_errors DESC;
|
||||
```
|
||||
|
||||
**`editPageText` failure reasons** (the most common real agent mistake — bad `find`):
|
||||
Note the v2 `tool` label is the part type (`tool-editPageText`); strip the `tool-`
|
||||
prefix if you join it against the legacy `toolName`.
|
||||
|
||||
**`editPageText` failure reasons** (the most common real agent mistake — bad `find`).
|
||||
Same dual-shape output source:
|
||||
|
||||
```sql
|
||||
WITH res AS (
|
||||
SELECT part->'output' AS o
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.metadata->'parts') part
|
||||
WHERE (m.metadata->>'toolTraceVersion') = '2'
|
||||
AND part->>'type' = 'tool-editPageText' AND part->>'state' = 'output-available'
|
||||
UNION ALL
|
||||
SELECT elem->'output' AS o
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array'
|
||||
WHERE (m.metadata->>'toolTraceVersion') IS NULL
|
||||
AND jsonb_typeof(m.tool_calls) = 'array'
|
||||
AND elem->>'toolName' = 'editPageText' AND elem ? 'output'
|
||||
)
|
||||
SELECT f->>'reason' AS reason, count(*)
|
||||
@@ -182,30 +249,43 @@ WHERE jsonb_typeof(o->'failed') = 'array'
|
||||
GROUP BY 1 ORDER BY 2 DESC;
|
||||
```
|
||||
|
||||
**Hard errors — persisted `error` field per tool (NEW rows, since #407)** — thrown
|
||||
tool failures now carry their real reason, so query them directly:
|
||||
**Hard errors — persisted `error` field per tool (v2 + post-#407 rows)** — thrown tool
|
||||
failures carry their real reason, so query them directly. On **v2** rows exclude the
|
||||
`interrupted` kind so an aborted call is not counted as a hard-fail:
|
||||
|
||||
```sql
|
||||
SELECT elem->>'toolName' AS tool, count(*) AS thrown_errors,
|
||||
min(elem->>'error') AS sample_error
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array' AND elem ? 'error'
|
||||
-- v2 rows label the kind; a legacy error element has no kind (count it).
|
||||
AND COALESCE(elem->>'kind', 'thrown') = 'thrown'
|
||||
GROUP BY 1 ORDER BY 2 DESC;
|
||||
```
|
||||
|
||||
Aborted mid-step calls on v2 rows are a distinct, directly countable population:
|
||||
|
||||
```sql
|
||||
SELECT elem->>'toolName' AS tool, count(*) AS interrupted
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array' AND elem->>'kind' = 'interrupted'
|
||||
GROUP BY 1 ORDER BY 2 DESC;
|
||||
```
|
||||
|
||||
**Hard-error proxy for OLD rows (pre-#407) — orphan gap per tool, WITH a spread column**
|
||||
(call parts minus result parts, plus how many distinct chats the gap is spread across).
|
||||
This covers rows written before thrown errors were persisted; on new rows a thrown
|
||||
failure now has its own `error` element (use the query above) and an orphan means only
|
||||
a genuinely aborted mid-step call:
|
||||
(call parts minus outcome parts, plus how many distinct chats the gap is spread across).
|
||||
This is needed ONLY for pre-#407 legacy rows (v2 and post-#407 rows carry the error /
|
||||
`kind` directly — use the queries above). The `WHERE` restricts to the legacy era so v2
|
||||
rows (where an `ok` outcome is not an `output`) never produce phantom orphans:
|
||||
|
||||
```sql
|
||||
WITH parts AS (
|
||||
SELECT m.chat_id, elem->>'toolName' AS tool,
|
||||
(elem ? 'input' AND NOT (elem ? 'output')) AS is_call,
|
||||
(elem ? 'output' OR elem ? 'error') AS is_result
|
||||
(elem ? 'input' AND NOT (elem ? 'output') AND NOT (elem ? 'ok')) AS is_call,
|
||||
(elem ? 'output' OR elem ? 'error' OR elem ? 'ok') AS is_result
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
WHERE jsonb_typeof(m.tool_calls) = 'array' AND m.role = 'assistant'
|
||||
AND (m.metadata->>'toolTraceVersion') IS NULL
|
||||
),
|
||||
per_chat AS (
|
||||
SELECT tool, chat_id, sum(is_call::int) - sum(is_result::int) AS gap
|
||||
@@ -261,11 +341,21 @@ WHERE tsv @@ websearch_to_tsquery('english', 'some phrase') LIMIT 20;
|
||||
|
||||
## Don't blow up your context
|
||||
|
||||
A single `tool_calls` row can be **300–400 KB** (results embed full page content and
|
||||
search payloads). Never `SELECT tool_calls` (or `jsonb_pretty(tool_calls)`) raw.
|
||||
Always project just the keys you need and truncate:
|
||||
Tool outputs embed full page content and search payloads (hundreds of KB per row).
|
||||
On **legacy** rows they are in `tool_calls`; on **v2** rows they moved to
|
||||
`metadata->'parts'` (the `tool_calls` trace itself is now small). Never `SELECT
|
||||
tool_calls` / `metadata` (or `jsonb_pretty(...)`) raw — project just the keys you need
|
||||
and truncate:
|
||||
|
||||
```sql
|
||||
-- v2: outputs live in metadata.parts
|
||||
SELECT part->>'type',
|
||||
left(regexp_replace((part->'output')::text, '\s+', ' ', 'g'), 200)
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.metadata->'parts') part
|
||||
WHERE (m.metadata->>'toolTraceVersion') = '2'
|
||||
AND part->>'state' = 'output-available' LIMIT 5;
|
||||
|
||||
-- legacy: outputs live in tool_calls
|
||||
SELECT elem->>'toolName',
|
||||
left(regexp_replace((elem->'output')::text, '\s+', ' ', 'g'), 200)
|
||||
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
|
||||
@@ -280,26 +370,32 @@ docker compose -p gitmost logs -f --tail=100 # whole stack
|
||||
```
|
||||
|
||||
Logging is `json-file`, `max-size=10m max-file=5` → ~50 MB retained, then rotated,
|
||||
and **wiped on container recreate**. Since the #407 fix, thrown-tool error text is
|
||||
**persisted in the `error` field** of `tool_calls` (see the hard-error query above), so
|
||||
you no longer depend on live logs for it. Logs/live UI remain useful for **pre-#407
|
||||
rows** (whose thrown errors were dropped) and for full stack traces beyond the
|
||||
truncated stored message. A per-tool `tool_calls_total{tool,status}` metric to
|
||||
VictoriaMetrics is still a possible future add for aggregate dashboards.
|
||||
and **wiped on container recreate**. Thrown-tool error text is **persisted** — in the
|
||||
`error` field of `tool_calls` (v2 `kind:'thrown'` / post-#407 legacy) — so you no longer
|
||||
depend on live logs for it. Logs/live UI remain useful for **pre-#407 rows** (whose
|
||||
thrown errors were dropped) and for full stack traces beyond the truncated stored
|
||||
message. A per-tool `tool_calls_total{tool,status}` metric to VictoriaMetrics is still a
|
||||
possible future add for aggregate dashboards.
|
||||
|
||||
## Gotchas checklist
|
||||
|
||||
- [ ] Counting every `tool_calls` element → **overcount**. Count `output` elements; add `error` elements for thrown failures (new rows), but don't count both as invocations.
|
||||
- [ ] `isError` / `success=false` ≈ 0 does **not** mean "no errors" — thrown errors are a separate `error` element (new rows) or dropped entirely (pre-#407 rows).
|
||||
- [ ] Thrown errors persist only on rows written **after the #407 fix** — pre-#407 rows still drop them (orphan only). Mind the cutover when trending over time.
|
||||
- [ ] **Check `metadata.toolTraceVersion` first.** v2 (`= 2`) has no output in `tool_calls`; legacy has it inline. Never trend a metric across the era boundary.
|
||||
- [ ] Counting every `tool_calls` element → **overcount**. Count OUTCOME elements — v2: `ok` or `error`; legacy: `output` or `error` — never both call+outcome as invocations.
|
||||
- [ ] `isError` / `success=false` ≈ 0 does **not** mean "no errors" — thrown errors are an `error` element (v2 `kind:'thrown'` / post-#407), not in the output.
|
||||
- [ ] **v2:** soft-error markers (the tool output) are in `metadata.parts`, NOT `tool_calls`. Legacy: they are in the `tool_calls` outcome `output`.
|
||||
- [ ] **v2:** `kind` splits a real hard-fail (`thrown`) from an aborted call (`interrupted`) directly — no orphan heuristic needed. The orphan gap is a pre-#407-legacy-only proxy.
|
||||
- [ ] `editPageText.failed` is `[]` on success — test for **non-empty**, not presence.
|
||||
- [ ] Orphan gap on OLD rows mixes thrown errors **and** aborted runs — split by tool. On NEW rows a thrown error is its own `error` element, so a gap ≈ aborted call.
|
||||
- [ ] `aborted` runs = server restarts, `failed` runs = provider overload — not agent mistakes.
|
||||
- [ ] Never dump a raw `tool_calls` cell — it can be hundreds of KB.
|
||||
- [ ] Logs are ephemeral (≤50 MB, wiped on recreate) — grab hard-error text live.
|
||||
- [ ] Never dump a raw `tool_calls` **or** `metadata.parts` cell — outputs are hundreds of KB.
|
||||
- [ ] Logs are ephemeral (≤50 MB, wiped on recreate) — grab pre-#407 hard-error text live.
|
||||
|
||||
## Snapshot (2026-07-07, illustrative — rerun the queries for current numbers)
|
||||
|
||||
> All rows in this snapshot predate #490, so they are **legacy-era** (outputs inline in
|
||||
> `tool_calls`, orphan proxy for thrown errors). Do not trend these numbers against v2
|
||||
> rows — segment by `toolTraceVersion` first.
|
||||
|
||||
|
||||
- 226 chats, 732 messages, 46 runs; ~4 400 real tool invocations.
|
||||
- Soft errors (persisted): `editPageText` 4/79 (bad/non-unique `find`) + 9 markdown-in-`find` warnings; `semanticSearch` 3/4 (`unavailable`); `Habr_update_draft_from_docmost` 1/2 (`doc` sent as object, not string).
|
||||
- Missing-result proxy, read WITH the spread column:
|
||||
|
||||
Reference in New Issue
Block a user