From 654ba9f249a4a8c6f42cf9705cb3919a68d03312 Mon Sep 17 00:00:00 2001 From: agent_coder Date: Thu, 9 Jul 2026 23:35:32 +0300 Subject: [PATCH 1/2] =?UTF-8?q?feat(ai-chat):=20=D0=BF=D0=B5=D1=80=D1=81?= =?UTF-8?q?=D0=B8=D1=81=D1=82=20tool-error=20=D1=87=D0=B0=D1=81=D1=82?= =?UTF-8?q?=D0=B5=D0=B9=20=E2=80=94=20=D1=83=D0=BF=D0=B0=D0=B2=D1=88=D0=B8?= =?UTF-8?q?=D0=B5=20=D1=82=D1=83=D0=BB=D1=8B=20=D0=B2=D0=B8=D0=B4=D0=BD?= =?UTF-8?q?=D1=8B=20=D0=B2=20=D0=B8=D1=81=D1=82=D0=BE=D1=80=D0=B8=D0=B8=20?= =?UTF-8?q?=D0=B8=20=D1=81=D0=BE=D1=85=D1=80=D0=B0=D0=BD=D1=8F=D1=8E=D1=82?= =?UTF-8?q?=20=D1=82=D0=B5=D0=BA=D1=81=D1=82=20=D0=BE=D1=88=D0=B8=D0=B1?= =?UTF-8?q?=D0=BA=D0=B8=20=D0=BF=D1=80=D0=B8=20=D1=80=D0=B5=D0=BF=D0=BB?= =?UTF-8?q?=D0=B5=D0=B5?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit В ai@6 упавший тул — это tool-error часть в step.content ({type,toolCallId, toolName,input,error}), а не элемент toolResults. Раньше serializeSteps писал только toolCalls+toolResults (ошибка терялась, orphan tool-call без результата), а assistantParts эмитил заглушку 'Tool call did not complete.' (реальный текст ошибки терялся для мультиходового реплея — модель не знала, почему упало, и повторяла ошибку). - StepLike расширен полем content; новый хелпер normalizeToolError (Error/string/ object -> строка, обрезка через существующий compactValue/лимиты). - serializeSteps: на каждый tool-error пушит парный {toolName, error} тем же паттерном, что успешный {toolName, output} -> колонка tool_calls фиксирует сбой. - assistantParts: при наличии tool-error эмитит output-error с РЕАЛЬНЫМ текстом; заглушка остаётся только для по-настоящему непарных вызовов (прерванных). - docs/reading-ai-logs.md обновлён под новую форму + cutover-оговорка. Обратно совместимо: старые строки читаются как раньше, error-элемент аддитивен. closes #407 Co-Authored-By: Claude Opus 4.8 (1M context) --- .../src/core/ai-chat/ai-chat.service.spec.ts | 86 +++++++++++++++ .../src/core/ai-chat/ai-chat.service.ts | 80 +++++++++++++- docs/reading-ai-logs.md | 100 ++++++++++++------ 3 files changed, 229 insertions(+), 37 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 9a08c8c9..945ebccd 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 @@ -148,6 +148,53 @@ describe('assistantParts', () => { expect(toolPart).not.toHaveProperty('output'); }); + it('replays the REAL error text for a THROWN tool (tool-error part)', () => { + const steps = [ + { + text: '', + toolCalls: [ + { toolCallId: 'c7', toolName: 'editPageText', input: { id: 'p1' } }, + ], + // A thrown tool is a `tool-error` content part; toolResults holds only + // successes and stays empty for this call. + toolResults: [], + content: [ + { + type: 'tool-error', + toolCallId: 'c7', + toolName: 'editPageText', + input: { id: 'p1' }, + error: new Error('page is locked'), + }, + ], + }, + ]; + const parts = assistantParts(steps, '') as AnyPart[]; + const toolPart = parts.find((p) => p.type === 'tool-editPageText'); + expect(toolPart).toBeDefined(); + expect(toolPart!.state).toBe('output-error'); + // The REAL error is replayed, NOT the 'Tool call did not complete.' placeholder. + expect(toolPart!.errorText).toBe('page is locked'); + expect(toolPart).not.toHaveProperty('output'); + }); + + it('keeps the placeholder ONLY for a call with neither result nor tool-error', () => { + const steps = [ + { + text: '', + toolCalls: [ + { toolCallId: 'c8', toolName: 'insertNode', input: { node: {} } }, + ], + toolResults: [], + content: [], // aborted mid-step: no result AND no tool-error + }, + ]; + const parts = assistantParts(steps, '') as AnyPart[]; + const toolPart = parts.find((p) => p.type === 'tool-insertNode'); + expect(toolPart!.state).toBe('output-error'); + expect(toolPart!.errorText).toBe('Tool call did not complete.'); + }); + it('skips malformed tool-calls (missing toolName or toolCallId)', () => { const steps = [ { @@ -195,6 +242,45 @@ describe('serializeSteps', () => { expect(trace[0]).toEqual({ toolName: 'getPage', input: { id: 'p1' } }); expect(trace[1]).toEqual({ toolName: 'getPage', output: { title: 'T' } }); }); + + it('records a THROWN tool failure (tool-error part) with its error message', () => { + const trace = serializeSteps([ + { + toolCalls: [{ toolName: 'editPageText', input: { id: 'p1' } }], + toolResults: [], + content: [ + { + type: 'tool-error', + 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', + }); + }); + + it('truncates a very long tool-error message to the tool-output limit', () => { + const long = 'x'.repeat(5000); + const trace = serializeSteps([ + { + toolCalls: [{ toolName: 'editPageText', input: {} }], + toolResults: [], + content: [{ type: 'tool-error', 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'); + }); }); 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 3fdf77d3..71d3071e 100644 --- a/apps/server/src/core/ai-chat/ai-chat.service.ts +++ b/apps/server/src/core/ai-chat/ai-chat.service.ts @@ -1637,6 +1637,17 @@ type StepLike = { toolName?: string; output?: unknown; }>; + // ai@6.0.134: a tool that THREW surfaces as a `tool-error` content part + // ({ type:'tool-error', toolCallId, toolName, input, error }), NOT as a + // `toolResults` entry (which holds only successes). Read from here so failed + // calls are persisted with their real error instead of being dropped. + content?: ReadonlyArray<{ + type?: string; + toolCallId?: string; + toolName?: string; + input?: unknown; + error?: unknown; + }>; }; /** @@ -1739,6 +1750,26 @@ function compactValue(value: unknown, depth: number): unknown { return value; } +/** + * Extract a bounded string message from a `tool-error` part's `error` field for + * persistence and history replay. The field may be an `Error`, a string, or an + * arbitrary object, so pull a message robustly. The result is passed through + * `compactValue` so a very long error honors the SAME truncation limits the file + * already applies to tool outputs (no new limit is introduced here). + */ +function normalizeToolError(error: unknown): string { + const message = + error instanceof Error + ? error.message + : typeof error === 'string' + ? error + : error != null && + typeof (error as { message?: unknown }).message === 'string' + ? (error as { message: string }).message + : String(error); + return compactValue(message, 0) as string; +} + /** * Rebuild the FULL UIMessage `parts` for an assistant turn from the SDK steps, * so multi-turn history replays prior tool-calls/results to the model (not just @@ -1771,6 +1802,14 @@ export function assistantParts( for (const r of step.toolResults ?? []) { if (r.toolCallId) resultsById.set(r.toolCallId, r.output); } + // Index this step's THROWN tool failures (ai@6 `tool-error` content parts) + // by tool call id, so a call that failed replays with its real error text. + 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 ?? []) { if (!call.toolName || !call.toolCallId) continue; const hasResult = resultsById.has(call.toolCallId); @@ -1783,9 +1822,21 @@ export function assistantParts( input: call.input, output: compactToolOutput(resultsById.get(call.toolCallId)), }); + } else if (errorsById.has(call.toolCallId)) { + // The tool THREW: replay the REAL error so the model on the next turn + // knows WHY the call failed (and does not blindly repeat it). An + // output-error round-trips through convertToModelMessages as a balanced + // tool-call + tool-result, keeping the rebuilt history valid. + parts.push({ + type: `tool-${call.toolName}`, + toolCallId: call.toolCallId, + state: 'output-error', + input: call.input, + errorText: normalizeToolError(errorsById.get(call.toolCallId)), + }); } else { - // No paired result (e.g. aborted mid-step). Persisting a bare - // tool-call (input-available) would replay as an unpaired call and + // No paired result AND no tool-error (e.g. aborted mid-step). Persisting + // a bare tool-call (input-available) would replay as an unpaired call and // throw MissingToolResultsError on the next turn (convertToModelMessages // emits no tool-result for it). Emit a SYNTHETIC paired result instead: // an output-error round-trips through convertToModelMessages as a @@ -2021,10 +2072,19 @@ export function serializeSteps( steps: ReadonlyArray<{ toolCalls?: ReadonlyArray<{ toolName?: string; input?: unknown }>; toolResults?: ReadonlyArray<{ toolName?: string; output?: unknown }>; + content?: ReadonlyArray<{ + type?: string; + toolName?: string; + error?: unknown; + }>; }>, ): unknown { - const calls: Array<{ toolName?: string; input?: unknown; output?: unknown }> = - []; + const calls: Array<{ + toolName?: string; + input?: unknown; + output?: unknown; + error?: string; + }> = []; for (const step of steps ?? []) { for (const call of step.toolCalls ?? []) { calls.push({ toolName: call.toolName, input: call.input }); @@ -2032,6 +2092,18 @@ export function serializeSteps( 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') { + calls.push({ + toolName: part.toolName, + error: normalizeToolError(part.error), + }); + } + } } return calls.length > 0 ? calls : null; } diff --git a/docs/reading-ai-logs.md b/docs/reading-ai-logs.md index 0583c7b3..ebe08a49 100644 --- a/docs/reading-ai-logs.md +++ b/docs/reading-ai-logs.md @@ -13,12 +13,14 @@ Read the **Gotchas** section before you trust any error count. - 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 at all.** Its error text is nowhere - in the DB — not in `tool_calls`, `content`, or `metadata`. It is shown live in - the UI only. So `isError` / `success=false` scans under-report by design. -- To find where agents fail you need **three** sources: (1) soft-failure markers in - `tool_calls`, (2) the orphan-gap proxy for thrown errors, (3) server logs / the - live UI for the actual error text. +- **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. ## Where the data lives @@ -85,25 +87,37 @@ 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 → NOT PERSISTED ❌ (the trap) +### 2. Hard failures — tool THREW → NOW PERSISTED ✅ (since the #407 fix) When a tool throws (the classic one is `patchNode` / `insertNode` / `tableUpdateCell` → `Failed to encode document to Yjs (fromJSON): Unknown node type: undefined`), the -runtime writes **no `tool-result` part**. The orphaned `tool-call` part stays, but -the error text is **nowhere in the DB**. It is streamed to the UI live and (until -rotation) to server logs — that is it. +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). -So any query like `count(*) FILTER (WHERE output.success = false)` will happily -return **0** for `patchNode` even when the chat is visibly full of red failures. -That is survivorship bias, not reliability. +**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: -The only DB-side proxy for a thrown error is an **orphan**: a `tool-call` part with -no matching `tool-result`. Caveat: 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 from real errors. Treat the -orphan gap as an *upper bound* on hard errors, 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. +- **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. + +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`. ### 3. Run-level failures → `ai_chat_runs` @@ -164,14 +178,28 @@ WHERE jsonb_typeof(o->'failed') = 'array' GROUP BY 1 ORDER BY 2 DESC; ``` -**Hard-error proxy — orphan gap per tool, WITH a spread column** (call parts minus -result parts, plus how many distinct chats the gap is spread across): +**Hard errors — persisted `error` field per tool (NEW rows, since #407)** — thrown +tool failures now carry their real reason, so query them directly: + +```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' +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: ```sql WITH parts AS ( SELECT m.chat_id, elem->>'toolName' AS tool, (elem ? 'input' AND NOT (elem ? 'output')) AS is_call, - (elem ? 'output') AS is_result + (elem ? 'output' OR elem ? 'error') 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' ), @@ -188,8 +216,12 @@ HAVING sum(gap) FILTER (WHERE gap > 0) > 0 ORDER BY missing_results DESC; ``` -**`missing_results` mixes thrown errors AND aborted/interrupted runs — you cannot -split them from `output` alone** (a positional "what follows the orphan" heuristic +The `is_result` predicate counts an `error` element as a paired result too, so on new +rows a persisted thrown error no longer inflates the orphan gap; a remaining gap is an +aborted/interrupted call. + +**On OLD rows, `missing_results` mixes thrown errors AND aborted/interrupted runs — you +cannot split them from `output` alone** (a positional "what follows the orphan" heuristic breaks on parallel tool batches, which persist as `call,call,…,result,result`). Use `chats_spread` to disambiguate: @@ -244,18 +276,20 @@ 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**. So thrown-tool error text is only reliably -caught **in real time** (or in the live chat UI, which renders the failed part with -its message). There is no durable, queryable store of hard tool errors today — if you -need one, that is a feature to add (persist `output-error` parts, or emit a -`tool_calls_total{tool,status}` metric to VictoriaMetrics). +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. ## Gotchas checklist -- [ ] Counting every `tool_calls` element → **2× overcount**. Count elements with `output`. -- [ ] `isError` / `success=false` ≈ 0 does **not** mean "no errors" — thrown errors aren't persisted. +- [ ] 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. - [ ] `editPageText.failed` is `[]` on success — test for **non-empty**, not presence. -- [ ] Orphan gap mixes thrown errors **and** aborted runs — split by tool before concluding. +- [ ] 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. From 96faa2822082ed8a4f54bff322082a9a433f76f6 Mon Sep 17 00:00:00 2001 From: agent_coder Date: Thu, 9 Jul 2026 23:50:05 +0300 Subject: [PATCH 2/2] =?UTF-8?q?docs:=20=D0=BE=D1=82=D1=80=D0=B0=D0=B7?= =?UTF-8?q?=D0=B8=D1=82=D1=8C=20=D0=BA=D0=BB=D1=8E=D1=87=20error=20=D0=B2?= =?UTF-8?q?=20=D0=B7=D0=B0=D0=B3=D0=BB=D0=B0=D0=B2=D0=BD=D0=BE=D0=B9=20?= =?UTF-8?q?=D1=81=D0=B5=D0=BA=D1=86=D0=B8=D0=B8=20reading-ai-logs=20(?= =?UTF-8?q?=D1=83=D1=81=D1=82=D1=80=D0=B0=D0=BD=D0=B8=D1=82=D1=8C=20=D0=BF?= =?UTF-8?q?=D1=80=D0=BE=D1=82=D0=B8=D0=B2=D0=BE=D1=80=D0=B5=D1=87=D0=B8?= =?UTF-8?q?=D0=B5)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Ревью #426: секция «How tool calls are stored — READ THIS» всё ещё утверждала, что единственные ключи элемента — toolName/input/output и «нет error», хотя этот же PR добавляет error и подробно описывает его ниже. Заглавный абзац приведён в соответствие: error — возможный ключ для брошенных ошибок на строках после #407; подсчёт инвокаций и пайринг учитывают error как парный результат. Co-Authored-By: Claude Opus 4.8 (1M context) --- docs/reading-ai-logs.md | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/docs/reading-ai-logs.md b/docs/reading-ai-logs.md index ebe08a49..fbf2e211 100644 --- a/docs/reading-ai-logs.md +++ b/docs/reading-ai-logs.md @@ -63,13 +63,17 @@ index 0: { "toolName": "getPage", "input": { "pageId": "…" } } ← tool-ca index 1: { "toolName": "getPage", "output": { … } } ← tool-result (has output, NO input) ``` -The **only** keys that ever appear on an element are `toolName`, `input`, `output`. -There is no `state`, no `errorText`, no `type`. Consequences: +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: -1. **Real invocation count = elements that have `output`.** Counting every element - double-counts (you get ~2× and a spurious "~50% of every tool has no output"). -2. **Pairing:** a successful call = a `tool-call` part followed by its `tool-result` - part. Both carry `toolName`, so you can group by tool on either. +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. ## The two classes of failure (and which the DB can see)