tai/logging.md

# logging.md

Extensive debug logging for tai, behind `--debug`. One `DebugLog`
owns three outputs: a sink (file, stdout, stderr), the vault `logs`
table, and nothing else. `LoggingDocTests` fails when this file
drifts from the code.

## Flags and sinks

`--debug` takes an optional sink: `--debug` alone means
`--debug file`, `--debug stdout` and `--debug stderr` redirect the
stream. `--debug-format` is `sentence` (default) or `json`.
`TAI_DEBUG` and `TAI_DEBUG_FORMAT` are env fallbacks when the flags
are absent. Without either flag or env var, logging is fully off:
no file, no rows, no overhead beyond one boolean check per hook.

The file sink is `<TAI_HOME>/debug.log`, one line per event,
flushed on every write so a crash loses nothing. File mode also
writes every event to the `logs` table when a store exists; modes
without a store (demo, mplex client, grr client) are file-only.
stdout/stderr sinks still write the table too: the sink only moves
the human stream.

## Wipe rule

The log file is wiped on the first write of a root process, and a
process is root when `TAI_CHILD` is unset. A child tai (currently
the `CapAnswerer` research spawn, which sets `TAI_CHILD=1`) appends
to whatever is there and never wipes. In-process workers (fork,
scheduler) share the open handle, so they neither wipe nor reopen.
Wipe-on-first-write, not wipe-on-boot, so `--version` and other
instant exits never destroy the previous log. Two concurrent roots
on one home are last-wipe-wins, documented, not prevented.

## Formats

Both formats carry the same fields: `ts` (UTC ISO), `level`,
`run` (per-process hex id, correlates everything one boot wrote),
`profile`, `bot`, `chat` (telegram chat id, else empty), then the
dotted event name, the message, and the meta map.

Sentence (default), free text last so the head splits cleanly:

```text
2026-10-18T12:01:02Z INFO run=ab12cd34 profile=work bot=main chat= component.event k=v k="quoted value" :: message
```

Meta values containing whitespace or quotes are double-quoted with
backslash escapes; everything before ` :: ` is whitespace-split
`key=value`, nothing else. JSON is one object per line with sorted
keys:

```json
{"bot": "main", "chat": "", "component": "agent", "event": "turn_end", "level": "INFO", "message": "turn finished", "meta": {"exec_ms": 12340, "steps": 4}, "profile": "work", "run": "ab12cd34", "ts": "2026-10-18T12:01:02Z"}
```

## Vault table

```sql
logs(id INTEGER PRIMARY KEY, profile, bot, chat, ts, run, level, component, event, message, meta_json)
```

Every filter column is indexed: `idx_logs_profile(profile, id)`,
`idx_logs_bot(bot)`, `idx_logs_chat(chat)`, `idx_logs_level(level)`,
`idx_logs_event(component, event)`, `idx_logs_run(run)`. An FTS
trigger indexes each row under `kind='log'` (`trg_logs_ai`, and
`trg_logs_ad` removes pruned rows), so `/search` and `fts_search`
rank log lines like any other vault text. `message` and `meta_json`
are sealed with `tai_enc` whenever the vault seal is enabled, and
unsealed only through `Store.log_query`, which takes the same
filters as the indexes plus `limit` and returns newest first.

The logger opens its own SQLite connection (WAL, 30s busy timeout,
one lock for all threads) instead of sharing `Store.db`, commits every row (so the logger
never holds a write transaction that could stall the main store
connection, and readers never lag), and prunes to `LOG_DB_KEEP`
newest rows every `LOG_DB_PRUNE_EVERY` inserts plus once per
configure. Logging never raises: a failed write is counted in
`dropped` and skipped.

## Caps

| Cap | Value | Meaning |
|---|---|---|
| `LOG_DB_KEEP` | 20000 | newest log rows kept per vault; older pruned with their FTS rows |
| `LOG_DB_PRUNE_EVERY` | 256 | inserts between prune checks |
| `LOG_MSG_MAX` | 2000 | message truncation, chars |
| `LOG_TEXT_MAX` | 4000 | each trapped text (system/user/assistant) in DB meta, chars |
| `LOG_PREVIEW` | 300 | each trapped text in the file sink, chars |
| `LOG_META_MAX` | 16384 | `meta_json` cap, bytes; oversized metas shrink longest strings first, so the stored JSON stays valid |

## The rules

R1. One event per interesting action, at exactly one site. No
action logs twice: `Tools.dispatch` covers all 61 tools, so no
`run_*` method logs; the bridge, the scheduler watcher, and the
serve dispatcher each log once for their layer.

R2. Level follows consequence, not volume. `INFO` for actions
taken, `WARNING` for retries and refused auth, `ERROR` for failed
operations and uncaught exceptions, `DEBUG` for durability
mutations (record/secret/schedule writes). There is no TRACE:
anything worth trapping is worth INFO.

R3. Every event carries the execution context it ran in: profile,
bot, chat (telegram only, else empty), and the process run id.
Callers pass what they know; the logger merges its sticky
defaults under explicit arguments.

R4. LLM completions trap the full accounting tuple: backend,
model, `exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`,
`cost_usd`, message char counts, the system, user, and assistant
texts (full to `LOG_TEXT_MAX` in the DB, previewed to
`LOG_PREVIEW` in the file), and the tool census: how many schemas
were actually sent, split into MCP, core, and lazy-native, plus
the sorted name list. Tokens are estimated at 4 chars each unless
a backend reports real usage (none do today); `cost_usd` is null
until a backend reports cost.

R5. Timed operations always log `exec_ms` as an integer. The
measurement wraps the operation, never the logging.

R6. Secret values, passphrases, keys, tokens, and header values
never reach a log. Names are fine (`secret_saved name=wifi`).
Every trapped text passes through `Store.redact` for its profile
before truncation, so a known value lands as `[redacted:NAME]`;
tool arguments whose key names a secret (`LOG_MASKED_ARGS`) are
masked to `***` before logging, which also covers values that are
not stored yet and therefore unknown to `redact`.

R7. Errors log where they are decided, with `short_error` text:
backend failure at the raise site, tool failure at dispatch, auth
refusal at the check, uncaught exceptions via `sys.excepthook`.
A catch that only re-raises or translates never logs.

R8. Hot paths never log: TUI render, input, and compositor paths,
token estimators, `redact` itself, FTS internals, health records,
and everything inside `DebugLog`. A hook in a per-keystroke or
per-frame path is a bug, not coverage.

R9. The logger never raises, never blocks on the network, never
touches a tool, and never calls back into logged code. A logging
failure is a dropped event, counted, not an error event.

R10. Child processes append, roots wipe (see Wipe rule). Log volume
is bounded by the caps above, never by sampling: pruning deletes
oldest first, deterministically.

R11. Sentence format keeps free text after ` :: ` and quotes any
meta value containing whitespace. JSON format sorts keys. Both are
line-delimited and greppable without a parser.

R12. New events extend the registry below with a fixed level, a
single site, and a fixed meta vocabulary (`exec_ms`, `tokens_in`,
`tokens_out`, `tokens_total`, `cost_usd`, `outcome`, `error`,
`steps`, `tools_sent`, `tools_mcp`, `tools_core`, `tools_lazy`,
`tool_names`, `*_chars`, `*_text`). A schema counts as MCP when
its name is not a native `TOOL_SCHEMAS` name. Synonyms are
rejected in review.

## Event registry

| Event | Level | Site | Meta |
|---|---|---|---|
| `app.boot` | INFO | `boot()` end | `version`, `home`, `mode`, `profile` |
| `app.exception` | ERROR | `sys.excepthook` | `error` |
| `agent.turn_start` | INFO | `run_turn` wrapper | `goal`, `capture`, `max_steps`, `depth`, `routed` |
| `agent.turn_end` | INFO | `run_turn` wrapper | `exec_ms`, `steps`, `tools_used`, `outcome`, `reply_chars` |
| `agent.verified` | INFO | `ensure_verified` end | `success`, `failures` |
| `agent.compact` | INFO | `compact_messages` end | `before_tokens`, `after_tokens`, `kept_turns` |
| `llm.completion` | INFO | `try_candidate` success | `backend`, `model`, `exec_ms`, `tokens_in`, `tokens_out`, `tokens_total`, `cost_usd`, `history_msgs`, `system_chars`, `user_chars`, `assistant_chars`, `system_text`, `user_text`, `assistant_text`, `tool_calls`, `retried_without_tools`, `tools_sent`, `tools_mcp`, `tools_core`, `tools_lazy`, `tool_names` |
| `llm.failed` | WARNING | `try_candidate` failure | `backend`, `model`, `error`, `transient` |
| `llm.round_retry` | WARNING | `complete()` before sleep | `round`, `pause_s`, `candidates`, `errors` |
| `llm.fatal` | ERROR | `complete()` wrapper on `BackendError` | `error` |
| `tool.call` | INFO | `Tools.dispatch` | `name`, `args`, `exec_ms`, `outcome`, `error`, `result_chars` |
| `approval.decision` | INFO | `ask_approval` wrapper | `command`, `decision`, `mode` |
| `vault.record_saved` | DEBUG | `add_record` end | `id`, `kind`, `size` |
| `vault.record_deleted` | DEBUG | `delete_record` end | `id` |
| `vault.secret_saved` | DEBUG | `save_secret` end | `name` |
| `vault.secret_deleted` | DEBUG | `delete_secret` end | `name` |
| `vault.schedule_saved` | DEBUG | `add_schedule` end | `id`, `name` |
| `vault.schedule_removed` | DEBUG | `remove_schedule` end | `id` |
| `vault.seal_rotated` | INFO | `rotate_seal` end | `home` |
| `vault.schema_upgraded` | INFO | `boot()` after print | `notes` |
| `sched.fired` | INFO | `scheduler_tick` after spawn | `id`, `profile`, `every_sec` |
| `sched.finished` | INFO | `watch_schedule` end | `id`, `status`, `result_chars` |
| `serve.request` | INFO | `dispatch_message` | `method`, `tool`, `session`, `exec_ms`, `outcome` |
| `serve.denied` | WARNING | `do_POST` auth check | `path` |
| `cap.run_start` | INFO | `cap_run_main` head | `sessions` |
| `cap.turn` | INFO | `CapFleet.ask` | `target`, `payload_chars`, `exec_ms`, `reply_chars`, `outcome` |
| `telegram.update` | INFO | `handle_telegram_update` wrapper | `chat`, `text_chars`, `reply_chars`, `voice`, `outcome` |

Outcomes are from a fixed set: `ok`, `error`, `denied`,
`unknown_tool`, `bad_args`, `timeout`. `goal`, `args`, `command`,
and all `*_text` values are redacted then truncated; `*_chars`
always reports the pre-truncation length.

## Validation against the source

Every registry site was checked before implementation: `boot`,
`run_turn`, `ensure_verified`, `compact_messages`,
`try_candidate`, `complete`, `Tools.dispatch`, `ask_approval`,
`add_record`, `delete_record`, `save_secret`, `delete_secret`,
`add_schedule`, `remove_schedule`, `rotate_seal`,
`scheduler_tick`, `watch_schedule`, `dispatch_message`, `do_POST`,
`cap_run_main`, `CapFleet.ask`, and `handle_telegram_update` all
exist with the shapes the hooks assume. Adjusted during review:
serve logging moved from `do_POST` (seven early returns) into
`dispatch_message` plus one auth line; scheduler completion moved
from `poll_agent` (shared, would double-log forks) into
`watch_schedule`; uncaught exceptions moved from a `main()` wrap
into `sys.excepthook`; `run_turn`, `complete`, and `handle_telegram_update` became thin
wrappers over renamed inners so their many exits log once;
`ask_approval` instead logs through an inline `decide()` closure,
because `TuiChatTests` calls it unbound on a stub that a rename
would break.

## Code map

`LOG_*` caps pin the bounds; `DebugLog` owns sink, format, run
id, wipe-on-first-write, the DB connection, prune, and redact;
module-global `LOG` is the one logger, inert until `configure()`;
`TAI_CHILD` selects append; `LOG_MASKED_ARGS` masks secret-shaped
tool arguments; `Store.log_query` reads rows back seal-aware.
`CapAnswerer.research` marks its child.

## Test hooks

`LoggingDocTests` asserts this file names every `LOG_*` cap, every
registry event, the `logs` table with its columns and indexes, the
`trg_logs_*` triggers, both flags, both formats, and `TAI_CHILD`,
with no em dash. `LoggerTests` covers formats, wipe/append,
redaction, prune, seal, `log_query`, the never-raise rule, and
representative hooks (dispatch, completion, approval, turn).