# Improve: Structured agent logging + troubleshooting guide

**Date:** 2026-04-17
**PR:** [#192](https://github.com/tidbcloud/investibook/pull/192)
**Affected files:** `backend/investibook/core/acp.py`, `docs/troubleshooting.md`

---

## Problem

Debugging agent tool execution (e.g. why `collect_evidence.py` was slow for a specific workspace) required querying the SQLite database's `messages_v2` table to extract tool output — a multi-step process involving `kubectl cp` of the DB file and `json_each()` SQL queries.

Meanwhile, the agent subprocess stderr was already captured but:
1. Logged via `print()` instead of `logger.info()` — no structured fields
2. Missing `workspace_id` — impossible to filter by workspace in Loki
3. Tool start/complete events lacked workspace context and output previews

---

## Changes

### acp.py: Structured log markers

| Marker | Before | After |
|--------|--------|-------|
| `agent_stderr` | `print(f"[{label} stderr] {line}")` | `logger.info("agent_stderr workspace_id=%s label=%s line=%s", ...)` |
| `tool_started` | (not logged) | `logger.info("tool_started workspace_id=%s tool_id=%s title=%s input_preview=%s", ...)` |
| `tool_completed` | `logger.info("tool_timing tool_id=%r started_at=%s duration_s=%s keys_before_pop=%s", ...)` | `logger.info("tool_completed workspace_id=%s tool_id=%s title=%s ok=%s duration_s=%s output_preview=%s", ...)` |

All log lines now include `workspace_id`, making them grep-able by workspace in both `kubectl logs` and Loki.

`tool_started` includes first 300 chars of input. `tool_completed` includes first 500 chars of output — enough to see script timing/errors without querying the DB.

### troubleshooting.md: Rewrite

Added two new sections:

**Section 3: Debugging Agent Execution via Logs** — log-first approach:
- Log marker reference table (agent_stderr, tool_started, tool_completed, etc.)
- `kubectl logs | grep` patterns for common debugging scenarios
- LogQL patterns for Loki queries
- Loki auth notes (session cookie required, API key won't work)

**Section 4: Querying the SQLite Database (Fallback)** — for when logs aren't enough:
- DB path: `/data/db/investibook.db` on the pod (PVC `investibook-data`)
- Full schema reference table (13 tables)
- Common SQL queries: message history, tool output extraction, tool performance ranking, token usage
- `json_each(parts)` pattern for extracting tool calls from messages

---

## Usage Examples

### Before (DB query required)

```bash
# 1. Copy DB from pod
kubectl cp deploy/backend:/data/db/investibook.db /tmp/investibook.db

# 2. Query tool output from messages
sqlite3 /tmp/investibook.db "
  SELECT json_extract(value, '$.title'), json_extract(value, '$.duration_ms')
  FROM messages_v2 m, json_each(m.parts)
  WHERE m.workspace_id = 'ws-XXXX' AND json_extract(value, '$.type') = 'tool'
"
```

### After (grep logs)

```bash
# Agent stderr (script progress, timing)
kubectl -n investibook logs deploy/backend --since=6h | grep 'agent_stderr.*ws-XXXX'

# Tool execution timeline
kubectl -n investibook logs deploy/backend --since=6h | grep -E 'tool_(started|completed).*ws-XXXX'

# Loki (for historical queries)
# {namespace="investibook",container="backend"} |~ "tool_completed.*ws-XXXX"
```

---

## DB access is still useful for

- Full tool output (logs only have 500-char preview)
- Message history reconstruction
- Token usage analysis across workspaces
- Bulk analysis across all workspaces (e.g. "which workspaces had the slowest tools this week")