From 48a074e0d2141c093e4d90fcdde08aae6c09a54f Mon Sep 17 00:00:00 2001 From: agent_coder Date: Sat, 11 Jul 2026 10:39:42 +0300 Subject: [PATCH] =?UTF-8?q?perf(ai-chat):=20=D1=84=D0=BE=D1=80=D0=BC=D0=B0?= =?UTF-8?q?=D1=82=20=D1=82=D1=80=D0=B5=D0=B9=D1=81=D0=B0=20tool=5Fcalls=20?= =?UTF-8?q?v2=20=E2=80=94=20outputs=20=D1=82=D0=BE=D0=BB=D1=8C=D0=BA=D0=BE?= =?UTF-8?q?=20=D0=B2=20parts=20(#490)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Каждый 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) --- .../src/core/ai-chat/ai-chat.service.spec.ts | 102 ++++++- .../src/core/ai-chat/ai-chat.service.ts | 103 +++++-- docs/reading-ai-logs.md | 252 ++++++++++++------ 3 files changed, 343 insertions(+), 114 deletions(-) diff --git a/apps/server/src/core/ai-chat/ai-chat.service.spec.ts b/apps/server/src/core/ai-chat/ai-chat.service.spec.ts index 8dd32123..cd32331a 100644 --- a/apps/server/src/core/ai-chat/ai-chat.service.spec.ts +++ b/apps/server/src/core/ai-chat/ai-chat.service.spec.ts @@ -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>; 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>; - // 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>; + 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>; 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>; + // 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', () => { diff --git a/apps/server/src/core/ai-chat/ai-chat.service.ts b/apps/server/src/core/ai-chat/ai-chat.service.ts index 22883d78..2a0fe557 100644 --- a/apps/server/src/core/ai-chat/ai-chat.service.ts +++ b/apps/server/src/core/ai-chat/ai-chat.service.ts @@ -2164,6 +2164,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 @@ -2431,7 +2440,7 @@ export function assistantParts( toolCallId: call.toolCallId, state: 'output-error', input: call.input, - errorText: 'Tool call did not complete.', + errorText: TOOL_CALL_INCOMPLETE_TEXT, }); } } @@ -2614,6 +2623,11 @@ export function flushAssistant( const metadata: Record = { 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). @@ -2654,42 +2668,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(); + for (const r of step.toolResults ?? []) { + if (r.toolCallId) resultIds.add(r.toolCallId); + } + const errorsById = new Map(); + 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', }); } } diff --git a/docs/reading-ai-logs.md b/docs/reading-ai-logs.md index fbf2e211..135085dc 100644 --- a/docs/reading-ai-logs.md +++ b/docs/reading-ai-logs.md @@ -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: ""}` 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: