Domovská stránka Prehľadávať Pomoc
Prihlásiť sa
clanker
/
clanker-saddle
1
0
Fork 0
Súbory Issues 0 Pull requesty 0 Wiki
Strom: 26ce7fe73a
Branche Tagy
clanker-saddle
/
docs
/
bug-exploration-report.md

bug-exploration-report.md 22 KB
História Raw

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 yields — 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.