gitmost/docs/reading-ai-logs.md

# Reading the AI dialog logs (how agents call tools, and where they fail)

How to inspect the agent conversation history in the database — and, more
importantly, the **one non-obvious trap that will make you report the wrong
answer**: the persisted history *silently hides hard tool failures*. Written from
real pain (a "which tools fail most?" analysis that confidently answered
"patchNode: 0 errors" while the UI was visibly full of red `patchNode` failures).

Read the **Gotchas** section before you trust any error count.

## 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.

## Where the data lives

Host `island.lc` (`10.31.40.120`), container `gitmost-postgresql`
(`pgvector/pgvector:pg18`), database `docmost`.

```bash
ssh island.lc
# one-off query:
docker exec gitmost-postgresql psql -U docmost -d docmost -P pager=off -c "SELECT ..."
# interactive:
docker exec -it gitmost-postgresql psql -U docmost -d docmost
```

The main app container is `gitmost` (`DATABASE_URL=postgresql://docmost:...@db:5432/docmost`).
All workspaces (vvzvlad / wb / asakusa / …) share this **single** database — they
are rows in `workspaces`, not separate deployments.

### Relevant tables

| Table | What it holds |
| --- | --- |
| `ai_chats` | one row per conversation (`title`, `role_id`, `page_id`, `creator_id`) |
| `ai_chat_messages` | every message; tool calls live in `tool_calls` jsonb |
| `ai_chat_runs` | one row per agent run (turn): `status`, `error`, `step_count` |
| `ai_agent_roles` | agent definitions (`instructions`, `model_config`) |
| `ai_mcp_servers` | configured MCP tool servers per workspace |

`ai_chat_messages` columns that matter: `role` (`user` | `assistant` — there is **no**
separate `tool` role), `content` (text), `tool_calls` (jsonb array), `metadata`
(jsonb, holds run `error` + rendered `parts`), `status`, `tsv` (full-text index).

## 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:

```text
index 0: { "toolName": "getPage",  "input":  { "pageId": "…" } }   ← tool-call   (has input, NO output)
index 1: { "toolName": "getPage",  "output": { … } }                ← tool-result (has output, NO input)
```

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` 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)

### 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:

| Tool(s) | Error marker in `output` |
| --- | --- |
| `editPageText` | `failed` is a **non-empty** array of `{find, reason}` (e.g. `text not found in the document`, `matches N times — provide a longer fragment or set replaceAll`). Also a soft `warning` when the `find` string contained markdown that only matched after stripping. |
| `semanticSearch` | `{ "unavailable": true, "reason": "semantic search unavailable" }` (feature/infra, not the agent's fault) |
| MCP passthrough (`Habr_*`, some `Search_*`) | `output` is an **array** (raw MCP content) whose text starts with `Error executing tool … validation error …` |
| generic | `output.isError = true` or `output.success = false` |

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)

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).

**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:

- **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`

`status` ∈ `succeeded | aborted | failed | running`; `error` holds the text. Seen in
the wild: `Run interrupted by a server restart.` (aborts) and
`Failed after N attempts. Last error: The service may be temporarily overloaded`
(LLM provider 529). These are infra/provider, not agent tool misuse.

## Ready-to-use queries

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):

```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'
GROUP BY 1 ORDER BY 2 DESC;
```

**Soft errors per tool** (everything the DB can honestly see):

```sql
WITH res AS (
  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'
)
SELECT tool, count(*) AS calls,
       sum(COALESCE(
         (o->>'isError') = 'true'
         OR (o->>'success') = 'false'
         OR (jsonb_typeof(o->'failed') = 'array' AND o->'failed' <> '[]'::jsonb)
         OR (o->>'unavailable') = 'true'
         OR o::text ~* 'error executing tool|validation error'
       , false)::int) AS soft_errors
FROM res GROUP BY tool HAVING sum(COALESCE(
         (o->>'isError') = 'true' OR (o->>'success') = 'false'
         OR (jsonb_typeof(o->'failed') = 'array' AND o->'failed' <> '[]'::jsonb)
         OR (o->>'unavailable') = 'true' OR o::text ~* 'error executing tool|validation error'
       , false)::int) > 0
ORDER BY soft_errors DESC;
```

**`editPageText` failure reasons** (the most common real agent mistake — bad `find`):

```sql
WITH res AS (
  SELECT 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->>'toolName' = 'editPageText' AND elem ? 'output'
)
SELECT f->>'reason' AS reason, count(*)
FROM res, jsonb_array_elements(o->'failed') f
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:

```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' 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'
),
per_chat AS (
  SELECT tool, chat_id, sum(is_call::int) - sum(is_result::int) AS gap
  FROM parts GROUP BY tool, chat_id
)
SELECT tool,
       sum(gap) FILTER (WHERE gap > 0)   AS missing_results,
       count(*) FILTER (WHERE gap > 0)   AS chats_spread,   -- disambiguates!
       max(gap)                          AS worst_single_chat
FROM per_chat GROUP BY tool
HAVING sum(gap) FILTER (WHERE gap > 0) > 0
ORDER BY missing_results DESC;
```

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:

- **spread across many chats** (e.g. `createComment` 96 over 29 chats) → a **systemic
  real error** (here: inline-comment anchor text not found on the page).
- **concentrated in one chat** (e.g. `searchInPage` 55, of which 51 in a single chat)
  → **one runaway/aborted session**, not a real per-call error — discount it.
- a gap on a **structural editor** (`patchNode`, `insertNode`, `tableUpdateCell`,
  `updatePageJson`, `transformPage`) is almost always a thrown Yjs-encode error.

**Run-level failures:**

```sql
SELECT status, count(*), min(error) AS sample_error
FROM ai_chat_runs GROUP BY status ORDER BY 2 DESC;
```

**Full-text search across messages.** The `tsv` GIN index is built as
`to_tsvector('english', unaccent(content))` — so it **stems English** but **not
Russian** (Russian lexemes are stored unstemmed, so only exact word forms match).
Most content here is Russian, so prefer `ILIKE` for substring search:

```sql
-- Russian / substring — reliable:
SELECT chat_id, left(content, 120)
FROM ai_chat_messages WHERE content ILIKE '%иранск%' LIMIT 20;

-- English phrase — can use the index:
SELECT chat_id, left(content, 120)
FROM ai_chat_messages
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:

```sql
SELECT elem->>'toolName',
       left(regexp_replace((elem->'output')::text, '\s+', ' ', 'g'), 200)
FROM ai_chat_messages m, jsonb_array_elements(m.tool_calls) elem
WHERE elem ? 'output' LIMIT 5;
```

## Server logs & live UI (for the error text the DB drops)

```bash
docker logs -f --tail=100 gitmost            # main app
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.

## 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.
- [ ] `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.

## Snapshot (2026-07-07, illustrative — rerun the queries for current numbers)

- 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:
  - **Systemic (spread) → real errors:** `createComment` 96 over **29 chats** (comment anchor text not found — the biggest real error hotspot); `editPageText` 31 over 12 chats (+ the 4 soft above); structural-editor Yjs throws `insertNode` 10 / `updatePageContent` 9 / `tableUpdateCell` 6 / `patchNode` 5 / `updatePageJson` 2 / `transformPage` 2.
  - **Concentrated → NOT real errors:** `searchInPage` 55 (51 in one chat); `Search_web_search` 15 & `Search_searxng_web_search` 6 (timeouts/aborts in long research sessions).
- Runs: 34 succeeded, 10 aborted (server restart), 1 failed (provider overload).