docs: bug exploration report (goal 3)

Report-only investigation of the web stack, saddle daemon push channel and test harness, verified against the live production database and running app.

Findings: systematic duplicated terminal tool_result with a fresh seq on every parked/finished session plus intermittent permanent seq holes (daemon-side; web ingestion exonerated); dashboard timeline LIMIT-before-noise-filter starves the feed during active agent work; event-log endpoints and page fully unauthenticated despite the unguessable-capability docblock claim (verified live, enumerable); SQL-equality saddle token comparison; exact-string goal verdict coupling; vacuous completion push gate after restart; resume-notice TOCTOU between report set and watermark; missing events scope index; README drift on the removed terminal-stream; minor render/doc nits. Includes a verified-correct section (allocation transaction, resume coalescing, lifecycle, queue math, guards, SSE framing, suites, co-dev trail) and a methodology appendix with the build-limitation note.

docs/bug-exploration-report.md

@@ -0,0 +1,421 @@
+# Bug exploration report — Clanker-Saddle web stack, saddle daemon, harness
+
+**Goal 3 (branch `goal/exploration`), investigation task on `task/3-15`.**
+Report-only: nothing in `src/`, `test/` or the live database was modified. Every
+finding below carries a reproduction a human can rerun.
+
+## Executive summary
+
+The goal/task/supervision machinery is fundamentally sound — the allocation
+transaction, the resume-notice coalescing, the goal lifecycle and the
+co-development git trail all behaved correctly under a live-data audit of 25
+sessions and ~4.8k ledger rows. The real defects cluster in two places: the
+**daemon-side event push channel** violates its own exactly-once seq contract on
+every session (a duplicated terminal `tool_result` under two different seqs) and
+intermittently drops a whole turn's worth of events (three sessions have
+permanent seq holes); and the **dashboard timeline** takes its `LIMIT 50` before
+filtering protocol noise, so it renders (nearly) empty exactly while an agent is
+working. A new medium-severity finding from this pass: the **event-log endpoints
+and page are completely unauthenticated** while their docblocks claim the task id
+is an "unguessable capability" — task ids are sequential integers, and
+unauthenticated enumeration of every task's full ledger (summaries, tool output,
+file paths) was verified live. Several lower-severity fragilities (SQL-equality
+token comparison, exact-string verdict coupling, a restart hole in the push gate,
+a resume-notice TOCTOU, missing ledger indexes) round out the list.
+
+Notation: `[severity | component]`, component one of `web` (the Vala app),
+`daemon` (the saddle daemon, binary-only here — behaviour documented as
+observed, web side exonerated where provable), `harness` (the Python test
+harness/suites).
+
+---
+
+## 1. Duplicated terminal `tool_result` on every parked/finished session
+
+`[medium | daemon]` — refined from "sessions 17 and 19" to **systematic**: every
+session in the live DB that ended via a terminal tool carries that terminal
+`tool_result` twice under two different seqs.
+
+**Evidence (live DB, read-only):**
+
+```
+sqlite3 -readonly /workspace/web-db.sqlite \
+  "SELECT session_id, json_extract(payload,'$.tool') AS tool, count(*)
+     FROM events WHERE session_id IS NOT NULL AND kind='tool_result'
+     AND json_extract(payload,'$.tool') IN ('finish','suspend','submit_plan','submit_report')
+    GROUP BY session_id, tool HAVING count(*)>0 ORDER BY session_id;"
+```
+
+Every one of the 20 terminated sessions shows `count(*) == 2` for its terminal
+tool (sessions 3, 12, 19 even show 3 for `suspend`). The stored shape around the
+boundary is, e.g. session 2 (rows by insertion id):
+
+```
+622|seq 432|tool_result|submit_plan {"ok":true,"status":"pending"}
+623|seq 433|lifecycle |{"event":"park","detail":"plan review"}
+626|seq 434|tool_result|submit_plan {"ok":true,"status":"pending"}   <- re-sent, NEW seq
+```
+
+and session 19: `seq 32 tool_result(suspend)`, `seq 33 lifecycle(park)`,
+`seq 34 tool_result(suspend)` — identical payload, new seq, interleaved with a
+goal-level `state_change` row.
+
+**Web side exonerated.** `EventService.store_pushed_events`
+(`src/Services/EventService.vala:86-135`) inserts each staged row and, on a
+UNIQUE(session_id, seq) violation, checks for the existing row and consumes the
+error — a *redelivered seq* is never duplicated. The duplicate rows carry
+*different* seqs, so they cannot be a web-side insert retry; and the web has
+exactly two `EventRecord` writers (the local `append` path, which never sets
+`session_id`, and the chunks push). Both duplicate copies carry `actor=harness`
+— only the daemon authors session-scoped rows. **The daemon re-emits the
+terminal tool_result after the lifecycle event, allocating it a fresh seq.**
+
+**Contract violated:** `SaddleChunksEndpoint` docblock
+(`src/Api/SaddleApi.vala:677-695`) — "`seq` is monotonic per session across all
+kinds; the batch stores idempotently on … UNIQUE(session_id, seq)" — and the
+README's "pushed chunks idempotent and ordered" claim. The idempotency the web
+provides is keyed on seq, so a same-payload-new-seq push is *stored twice* by
+design.
+
+**Impact:** the event-log page and any replay/audit consumer see the terminal
+handshake twice per session; per-session event counts and seq arithmetic are
+permanently off.
+
+**Why the harness misses it (audit pass d):** `test/harness.py` `push_events`
+(line 571) auto-fills a missing seq from `next_push_seq()` (lines 609-612), a
+strictly incrementing per-session counter — the fake *cannot* emit a
+duplicate-with-new-seq. The suites assert web-side idempotency for a
+*redelivered* seq (which works) and never model the daemon's post-lifecycle
+re-send.
+
+**Fix direction (daemon-side):** emit the terminal `tool_result` exactly once
+before the lifecycle event and reuse the same seq on any re-send, or make the
+web treat `(session_id, kind, payload)` for terminal kinds as idempotent too.
+
+## 2. Intermittent permanent seq holes — a whole turn's events lost
+
+`[medium | daemon]`
+
+**Evidence (live DB, read-only):**
+
+```
+sqlite3 -readonly /workspace/web-db.sqlite \
+  "SELECT session_id,count(*),count(DISTINCT seq),min(seq),max(seq)
+     FROM events WHERE session_id IS NOT NULL GROUP BY session_id
+    HAVING count(*)!=count(DISTINCT seq) OR max(seq)!=count(*) ORDER BY session_id;"
+-- 1|177|177|1|179   (seq 69 AND 70 missing — the prior pass recorded one; it is two)
+-- 17|140|140|1|141  (seq 137)
+-- 19|33|33|1|34     (seq 31)
+```
+
+Session 1's gap is mid-run, between two ordinary `usage` rows (68 and 71) — the
+model's turn-19 `turn_text` + `tool_call` + `tool_result` never arrived. All
+three gaps sit adjacent to (but distinct from) the finding-1 duplication sites.
+The current session (25, this investigation) stayed contiguous across 340+ seqs
+while watched — the loss is intermittent, consistent with a daemon-side flush
+path that can drop a batch around park/finish boundaries.
+
+**Web side exonerated:** same argument as finding 1 — the store path is
+append-only per seq and cannot skip; nothing on the web side deletes events.
+
+**Impact:** permanent gaps in the audit ledger; a replay consumer cannot trust
+seq contiguity; the "exactly-once, monotonic" contract in the chunks docblock is
+falsified.
+
+**Fix direction (daemon-side):** audit the daemon's outbox flush around
+park/finish (`/workspace/.saddle-outbox/session-*/outbox.jsonl` is the queue —
+one JSON line per batch, seq assigned at enqueue time; a crash or an early
+exit between enqueue and flush, or a second writer, would produce exactly this
+signature).
+
+## 3. Event-log endpoints and page are unauthenticated
+
+`[medium | web]` — **new finding this pass.**
+
+**Evidence:** `src/Api/EventLogApi.vala:20-24` documents "Both are
+unauthenticated like the terminal stream before them (the task id is an
+unguessable capability)"; `src/entrypoints/TaskLogEntrypoint.vala:33-35`
+repeats "Unauthenticated like the terminal page before it (the task id is the
+capability)". Task ids are sequential integers (`AUTOINCREMENT`), and every
+other task surface is login-gated (`TaskDetailEntrypoint.vala:516` calls
+`SpryAuth.require_login`; the log entrypoint calls nothing).
+
+Verified live, unauthenticated (no cookie):
+
+```
+curl -s "http://clanker-web:8080/tasks/1/events?limit=3"   # 200 + full payloads
+curl -s -o /dev/null -w "%{http_code}" "http://clanker-web:8080/tasks/1/log"   # 200
+for t in 1 2 3 4 5; do curl -s "http://clanker-web:8080/tasks/$t/events?limit=1"; done
+# all five return data — enumeration is trivial
+```
+
+The returned payloads include task completion summaries (full markdown reports),
+`run_command` tool calls with the exact shell commands (file paths, DB paths),
+and their stdout — the same content the login-gated task page shows.
+
+**Impact:** anyone with network reach to the app reads every task's transcript.
+On this deployment the app is container-internal, but nothing in the code
+enforces that, and the docblock's stated justification is simply false.
+
+**Why tests miss it:** the harness' `slot_public`/page assertions authenticate
+by design; no bundle asserts a 401/redirect on these routes (the plan-17 work
+inherited the terminal stream's open access without inheriting a reason for it).
+
+**Fix direction:** route the three paths through `SpryAuth.require_login` (or
+issue a per-task capability token in the page and require it on the API), and
+fix the docblocks either way.
+
+## 4. Dashboard timeline goes blank while an agent works
+
+`[medium | web]`
+
+**Evidence:** `src/Services/TimelineService.vala:71` applies
+`.order_by_desc(expr("id")).limit(WINDOW)` (WINDOW=50) on the *raw* ledger and
+only then filters the noise kinds in the in-memory loop at lines 90-93
+(`turn_text`, `tool_call`, `tool_result`, `command_output`, `usage`), plus
+goal-run task rows at lines 94-99. Measured live mid-investigation (an agent —
+me — actively working):
+
+```
+sqlite3 -readonly /workspace/web-db.sqlite \
+  "SELECT kind,count(*) FROM (SELECT kind FROM events ORDER BY id DESC LIMIT 50)
+    GROUP BY kind ORDER BY 2 DESC;"
+-- tool_result|15  tool_call|15  usage|11  turn_text|7  progress|2
+```
+
+48 of the newest 50 rows are noise → the dashboard timeline renders at most 2
+entries exactly when a user is watching an agent work. README line 49 promises
+"a cross-task activity timeline (last ~50 events, newest first)". Over the
+newest 500 rows, 50 are non-noise — the data exists; the window just cuts it
+off. Secondary note: the window is newest-50-by-`id`, then insertion-sorted by
+epoch (`created_at`) with id as tiebreak (lines 74-85) — correct for
+same-process writes but worth knowing the sort key is the row's *event* epoch,
+not insertion order, whenever clocks matter.
+
+**Why tests miss it:** `test/bundles/allocation.py:525-548` seeds exactly two
+sparse human-ish rows a few seconds old and asserts they appear — the fixture
+DB never holds 50 consecutive noise rows, so limit-before-filter cannot starve.
+
+**Fix direction:** filter first (either in SQL with a `kind NOT IN (...)`
+clause or by raising the fetch bound and filtering in memory) so "last ~50
+events" means the last 50 *timeline-visible* events.
+
+## 5. Saddle bearer tokens compared by SQL string equality
+
+`[low/medium | web]`
+
+**Evidence:** `src/Services/SaddleService.vala:212-219` — `saddle_for_token`
+does `db.query<Saddle>().where(expr("token == $0", elem(token)))`. Equality on
+an indexed(?) text column short-circuits per byte in SQLite, so the comparison
+time leaks token-prefix match length — the classic timing side-channel class.
+Tokens are 122-bit random (`Uuid.string_random()` minus hyphens,
+`SaddleService.vala:169`), stored in plaintext, with no revocation audit trail
+beyond row deletion. Practical exploitability is low (network-adjacent attacker
+with high-precision timing), but the pattern is worth recording; contrast the
+password path, which correctly uses argon2id (`spry_users.password_hash` = 
+`$argon2id$v=19$m=262...` in the live DB).
+
+**Fix direction:** hash tokens at rest and compare digests
+(e.g. `crypto.timing_safe_eq`-equivalent / HMAC), or at minimum compare outside
+SQL.
+
+## 6. Goal verdicts are exact-string coupled
+
+`[low | web]`
+
+**Evidence:** the four stable wordings live at `src/Services/TaskService.vala:61-64`
+(`NOTICE_PLAN_APPROVED` = "Plan approved. Proceed with implementation.",
+`NOTICE_REVIEW_APPROVED` = "Review approved. Continue with the task.", plus the
+two feedback prefixes). `GoalService.answer_block` branches on
+`answer == NOTICE_PLAN_APPROVED` (line 677) and `answer == NOTICE_REVIEW_APPROVED`
+(lines 686 and 713); `TaskService` line 918 mirrors it. Any writer that
+paraphrases (an API client, a script, a future UI) silently lands in the reject
+branch — the goal flips back to `planning`/`active` with no error. The web's own
+form builds the wording server-side (`AnswerBlockAction`), and the live DB
+confirms all 7 stored block answers are byte-exact constants (task_blocks ids
+1-7), so the coupling holds today. Documented-as-deliberate (plan 11: the
+wording rides the resume notice verbatim) — report it as a coupling risk: the
+approved-set membership test should at least be centralised in one predicate
+with the constant list, and any non-web answer path documented as
+contract-bound.
+
+Related render nit: `GoalDetailEntrypoint.vala:610` sets
+`approved = block.answer != null && block.answer == NOTICE_PLAN_APPROVED` — an
+*approved completion review* (answer = `NOTICE_REVIEW_APPROVED`) never badges as
+approved in the revision history (`goal_detail.html:322` keys off `revision.approved`),
+so an accepted completion renders with the same "answered" styling as a
+rejected one.
+
+## 7. Completion-accept push gate passes vacuously after a restart
+
+`[low | web]`
+
+**Evidence:** `GoalService.refuse_unpushed_origin` (lines 1289-1319) resolves
+the run's saddle, then reads `polls.goal_branches_for(saddle_id)`; when the raw
+string is empty (never probed — which is the state after every app restart, or
+for an older daemon that never reports `goal_branches`) it returns without
+raising, and the accept proceeds. The in-memory `SaddlePollState` holds no
+persistent probe snapshot by design ("live probe state only, NEVER a stored
+snapshot on the goal row" — `SaddlePollState.vala:82-90`). The daemon-side
+push rule remains the enforcing layer, so this is a defense-in-depth hole, not
+the primary gate; record it so nobody mistakes an empty-probe accept for a
+verified push. The goal page's push chips have the same vacuous-render property
+(`GoalDetailEntrypoint.vala:905-920` renders no chips until a probe lands —
+arguably correct for display, but the operator can accept a completion while
+looking at zero chips).
+
+**Fix direction:** refuse (or at least warn) when the gate cannot see probe
+data for a saddle that *should* report branches, rather than treating
+"no data" as "pushed".
+
+## 8. Resume-notice TOCTOU: report set and watermark read at different "now"s
+
+`[low | web]` — **new finding this pass.**
+
+**Evidence:** `GoalService.take_resume_notice` (lines 1173-1256) builds the
+"New completion reports" set from one query pass (the `finished` vector is
+filled at lines ~1196-1203 using `since` = the run's `suspended_at`), then —
+after several intervening `yield`s — computes the consumed watermark at lines
+1236-1248 (`newest_terminal_transition` + a second `completed_at` pass over the
+task rows) and writes `last_terminal_watermark = consumed` (line 1253). A task
+that completes *between* the two reads is included in neither the report set
+(already queried) nor… it *is* included in the watermark pass (its `completed_at`
+is now visible) — so its report is marked consumed without ever being embedded.
+The next park window starts from the advanced watermark and never re-reports it.
+
+Live data shows the window held every time it mattered (#8 in s6, #9 in s9,
+#10+#11 in s18, #12+#13 in s22 — each embedded exactly once, no
+double-embedding; #11 completed 14:35:43 and *did* appear in the notice built
+at 14:35:44), so this is a narrow race, not an observed loss. Note also the
+two cursors are different fields by design: the report set keys on
+`run.suspended_at` (park stamp, set once per park at `TaskService.vala:1193`,
+cleared on resume at 1319-1327) while `resume_due` (lines 1110-1153) keys on
+`last_terminal_watermark` — since `suspended_at < resume < consume`, the
+watermark write cannot strand a transition that the *resume* path still owes.
+
+**Fix direction:** compute the report set and the watermark from one snapshot
+(a single transaction or one query whose result feeds both), or clamp the
+watermark to the newest `completed_at` actually *included* in the report.
+
+## 9. Events ledger has no scope index — every reader full-scans
+
+`[low | web]` — **new finding this pass.**
+
+**Evidence:** the events table's only index is the UNIQUE(session_id, seq)
+constraint (`sqlite_master` shows just `sqlite_autoindex_events_1`). Every hot
+reader filters on `(scope_type, scope_id)` and orders by `id`:
+`page_for_task` (EventService.vala:145-162), `newer_than` (165-175),
+`list_for_task`/`list_for_goal` (181-200), `newest_terminal_transition`
+(244-265), `last_session_activity` (292-305 — which additionally walks *all*
+rows of the session oldest-first to keep the last, O(n) per staleness probe),
+plus the timeline's newest-50 scan. With ~4.8k rows nothing is observable, but
+the per-task event-log page and the 1 Hz SSE cursor walk are full scans that
+grow linearly with the whole ledger. Also note `newest_activity` (280-289)
+fetches with a kind filter then takes the first row — fine — but its callers
+sit on the same unindexed predicate.
+
+**Fix direction:** add `CREATE INDEX idx_events_scope ON events (scope_type,
+scope_id, id)` in a migration; consider `ORDER BY id DESC LIMIT 1` shapes for
+the "newest" accessors.
+
+## 10. Documentation drift: README describes a removed SSE surface
+
+`[low | docs]`
+
+**Evidence:** README "Realtime channels and the browser's SSE budget" (lines
+465-472) still documents "one `/terminal-stream` per open terminal tab" and
+hidden-tab stream-closing mitigations. Plan 17 replaced the terminal view with
+the event log; `grep -rn terminal-stream src/` matches only a comment
+(`src/pages/task_detail.html:32`). The budget concern is still real (the event
+log's SSE stream is one-per-open-tab, same shape), but the named endpoint and
+the described mitigation do not exist in the code.
+
+**Fix direction:** rewrite the section against `/tasks/{id}/events/stream`.
+
+## 11. Minor: dead docblock and duplicated constant knowledge
+
+`[cosmetic | web]`
+
+- `src/entrypoints/GoalDetailEntrypoint.vala` ~line 958: the comment `/** A
+  flattened, clipped activity line (the current-activity display). */` is
+  immediately followed by *another* docblock for `activity_line_of` — the first
+  one documents nothing (leftover from a removed helper).
+- `clip_line` uses a Unicode ellipsis `…` inside a Vala string; per goal 1's
+  findings the compiler's template escaping is not involved in service code, so
+  this is safe, but it sits adjacent to the ASCII-invariant sweep's territory —
+  noted so a future sweep knows it was considered.
+
+---
+
+## Verified correct (negative results — do not "fix" these)
+
+Re-verified this pass; a future fixer should not churn them:
+
+- **Allocation claim transaction** (`AllocationService.claim_candidate`,
+  `src/Services/AllocationService.vala:218-300`): single `BEGIN IMMEDIATE`,
+  fully synchronous body (no awaits between re-validation and writes), offline
+  re-check, straggler open session closed `parked`, fresh session row on
+  resume. Concurrent asks resolve to exactly one winner.
+- **Resume-notice coalescing** (`take_resume_notice` + `resume_due`): verified
+  against all four park windows in goal 2 — each new completion report embedded
+  exactly once, watermark advanced, statuses section and reports section never
+  double-embed the same body (plan 16 S3 holds).
+- **Goal lifecycle in live data**: goal 2 sits in `completion_review` with
+  block 6 (created 2026-09-19 00:11:22) unanswered — the correct waiting state
+  after a rejected first review (block 5, feedback answer) and a re-submitted
+  report; every state_change/plan_submitted event reconciles with the block
+  rows and session parks.
+- **Dashboard queue-card math** (`HomeEntrypoint.DashboardState.build`):
+  goal-run exclusion except suspended, ready-subset gating for queued,
+  answered-block blocked→queued promotion, draft separation — matches the
+  README's Queue-card contract.
+- **User guards**: `is_last_enabled_admin` (UserActions.vala:75-90) protects
+  the last enabled admin from disable/demote; self-modify paths refuse
+  self-disable and self-demote.
+- **Password hashing**: argon2id (`$argon2id$v=19$m=262...`) in `spry_users`;
+  saddle tokens 122-bit random.
+- **SSE framing** (`EventStreamSseEndpoint`, EventLogApi.vala:86-131): initial
+  window oldest-first with `id:` lines, then a 1 Hz cursor walk appending newer
+  rows, `retry: 3000` hint, `ping` heartbeats on quiet seconds — verified live
+  by streaming my own session. The frames carry no `event:` name (message
+  events only), which the task-log client (`stream.onmessage`) correctly
+  consumes — the plan-17 fix holds.
+- **Standalone suites**: `test/test_template_ascii.py` (1 test) and
+  `test/test_task_log_js.py` (52 tests) pass in this container.
+- **Co-development trail (goal 2 / tvproxy)**: task branches merged into
+  `goal/overnight-improvements` (merge commits `e0b817e`, `de2e79c`, `8694852`,
+  `07a7fc8`), worktrees pruned (`git worktree list` shows only the goal clone),
+  goal branch pushed and equal to `origin/goal/overnight-improvements`. The
+  merge/push pipeline behaves.
+- **Dispatcher wake/guard arithmetic** (Dispatcher.vala:166-265):
+  `wake_pending` (`< guard`) and `wake_overdue` (`>= guard`) partition the
+  window exactly; affine-first for parked tasks with derived-free + ask-capable
+  checks; lost-wake guard offlines and the same tick's wake pass re-offers.
+  Restart-wipes-ask-state is a documented trade-off, not a bug.
+
+---
+
+## Methodology appendix
+
+- **Static audit** of the Vala web app (~16k lines: services, actions, API,
+  migrations, entrypoints) and the Python harness (~3.5k lines), focused on the
+  surfaces the goal plan flagged plus the render paths, poll state, SSE APIs and
+  README claims audited this pass.
+- **Live-data audit** of the production database this very session writes to
+  (`/workspace/web-db.sqlite`, read-only via `sqlite3 -readonly`): 25 sessions,
+  ~4.8k events, 3 goals, 14 tasks, 7 blocks — used as the behavioural oracle
+  for findings 1, 2, 4, 6, 8 and the negative results.
+- **Live-service audit**: unauthenticated HTTP probes against the running app
+  (`http://clanker-web:8080`) for finding 3 and the SSE framing check; the
+  daemon's outbound queue (`/workspace/.saddle-outbox/session-25/outbox.jsonl`)
+  inspected read-only to characterise the push channel.
+- **Dogfooding**: this investigation runs *on* the stack under investigation —
+  its own session (25) doubled as the live probe for seq continuity and
+  timeline noise ratios.
+- **Build limitation**: spry/statum/astralis dev libraries are absent in this
+  container, so the app binary cannot be rebuilt (`meson setup` fails at
+  dependency resolution — not attempted). The two standalone Python suites run
+  green; the live production instance served as the behavioural oracle instead.
+- **Daemon source** is not present (binary at `/usr/libexec/saddle/saddle`), so
+  daemon-side findings (1, 2) are documented as observed behaviour with the web
+  side exonerated by code inspection and insertion-order evidence.