diff --git a/VERSION b/VERSION index 930e300..e867cc2 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -0.14.1 +0.14.2 diff --git a/plans/2026-07-30-session-review-plan-drift-and-dead-activity-panel.md b/plans/2026-07-30-session-review-plan-drift-and-dead-activity-panel.md new file mode 100644 index 0000000..2273ac4 --- /dev/null +++ b/plans/2026-07-30-session-review-plan-drift-and-dead-activity-panel.md @@ -0,0 +1,293 @@ +# 2026-07-30 — Session review: plan drift & a dead activity panel + +**Status:** Done — 2026-08-03. Shipped in `467589d` (v0.14.1), deployed to +production. The two operator-reported complaints are resolved and verified on +the bug-report session itself (`398f5eda`); see [Resolution](#resolution-2026-08-03) +at the end. Items P0.1, P0.2 (fix 1+2), P1.1, P1.2 are complete; P0.2 fix 3, +P2.1, P2.2 are deferred (the reported symptoms no longer reproduce). + +**Scope:** The five most-recently-active `agent:nomos` sessions by +`last_active_at`, pulled from the live Postgres on 2026-07-30, plus the +code paths they exercise (`cmd/nomos/store.go`, `cmd/nomos/tasks.go`, +`web/src/lib/stores/{activity,workspace,chat}.ts`, +`web/src/lib/components/UnifiedTimeline.svelte`). +**Trigger:** Operator report — "the plan was off, the activity sidepanel +was not kept up to date and feels off, not live." + +Both complaints are real, both reproduce deterministically, and both have +a single-line root cause. They are *not* the same bug, but they compound: +the plan bug produces the exact event stream that the activity panel +silently discards. + +--- + +## Sessions reviewed + +| # | sid | goal (short) | outcome | activity rows | plan gens | re-planned? | +|---|---|---|---|---|---|---| +| 1 | `398f5eda` | hubris recurring network outage → EEE mitigation | success | 48 | 2 | **yes** | +| 2 | `0a49ba3d` | triage active signals on host:strong | success | 30 | 1 | no | +| 3 | `9368633d` | sensor temperatures on host:strong | success | 12 | 1 | no | +| 4 | `2065a29a` | temps → pivot to "fun fact about chickens" | success | 18 | 2 | **yes** | +| 5 | `bad26076` | greeting / responsiveness test | success | 6 | 1 | no | + +**Score: 5 success / 0 partial / 0 failed.** The agent's *reasoning* was +fine in all five. Every defect below is in the bookkeeping and the +rendering — the parts the operator actually looks at. + +**The correlation that matters: both sessions that re-planned (`398f5eda`, +`2065a29a`) recorded a corrupt plan. Neither of the three that didn't +re-plan did.** Re-planning was a 100% failure path (pre-fix). + +--- + +## P0.1 — `update_plan_step` addresses the wrong plan generation + +This is "the plan was off," and it was fully deterministic. + +`proposePlan` numbered a new generation's steps *continuing* from the old +one (`store.go:937`): + +```go +seq := startSeq + i + 1 // startSeq = MAX(seq) of all prior steps +``` + +So on generation 2 of `398f5eda`, the six new steps landed at **seq 7–12**. + +But the tool result the model got back never mentioned those numbers +(`tasks.go:282`): + +``` +"Plan set (6 steps). If all steps are read-only, execute now — …" +``` + +…while `update_plan_step`'s schema told it (`tasks.go:81`): + +```go +"seq": "1-based step number from propose_plan." +``` + +The model had no way to learn the real seq numbers and was explicitly told +to use 1-based ones. It did exactly that. + +**What the DB recorded for `398f5eda`:** + +``` +20:07:40 propose_plan → gen 2 created at seq 7..12 + gen 1 (seq 1..6) marked `replaced` +20:08:10 update_plan_step seq=1 running ← hits gen-1 step 1 +20:08:18 update_plan_step seq=1 done ← resurrects a `replaced` row +20:08:18 update_plan_step seq=2 running +… +20:09:57 complete_task +``` + +Result — the persisted plan was a lie in three separate ways: + +- **Steps 1–5 (the abandoned "force 1Gbps" plan) show `done`** with real + start/finish timestamps. Work that was never performed was recorded as + performed. `updatePlanStep` wrote status by seq with no guard, so it + happily flipped `replaced` → `running` → `done`. +- **Steps 7–12 (the actual EEE work that ran) had `started_at = NULL`** + and were bulk-closed to `done` by `completeTask`'s auto-close sweep + (`store.go:1096`) at 20:09:57 — all six sharing one timestamp. +- **The panel shows 12 steps**, because `getPlanSteps` returned every + generation unfiltered (`store.go:1356`) and the frontend never reads the + `generation` field at all (`grep generation web/src` → zero hits outside + the API type). + +`2065a29a` had the identical signature: gen 2 at seq 4–5, gen-1 steps 1 +and 2 flipped to `done`/`skipped` four seconds later. + +### Fix (implemented) + +1. **Make seq generation-relative.** `proposePlan` resets seq to `1..N` per + generation; `(session_id, generation, seq)` is the addressing key. + `updatePlanStep` resolves against `MAX(generation)`. This matches what + the model naturally does and what every prompt already says. +2. **Return the seq numbers to the model.** The `propose_plan` result now + enumerates them (`1=…; 2=…`). +3. **Refuse writes to superseded rows.** `updatePlanStep` addresses only + the current generation; a stale/out-of-range seq returns + `errPlanStepNotFound` (never resurrects a `replaced` row). +4. **Filter by generation on read.** `getPlanSteps` returns only + `MAX(generation)` by default; `?all=true` for the audit/eval view. +5. **Stamp `started_at` in the auto-close sweep.** `completeTask` closing + a step sets `started_at = COALESCE(started_at, now())`. + +A migration (`029`) renumbers existing rows to per-generation `1..N` and +replaces the `(session_id, seq)` index with a unique +`(session_id, generation, seq)`. + +--- + +## P0.2 — The activity panel invents its own timestamps + +This is "not live / feels off," and it was worse than a staleness bug: the +times on screen were **fabricated at render time**. + +`activity.ts:118` — every tool entry: + +```ts +timestamp: now - ($msgs.length - mi) * 1000 +``` + +`now` was `Date.now()` captured at the top of `computeActivityLog`. So a +tool call's displayed time was *"the moment this function last ran, minus +one second per message from the end."* Not when the call happened. + +Three consequences, all of which read as "not live": + +- **The clock was wrong.** `UnifiedTimeline` rendered these through + `hhmm()` / `hhmmss()`, so opening yesterday's session showed every step + timestamped *right now*, one second apart. +- **It churned every 3 seconds.** The message poller re-set `messages` + unconditionally on every tick, which re-derived `activityLog`, which + re-captured `now`. Every entry's timestamp marched forward 3s at a time, + forever. Motion with no information. +- **Real and fake timestamps sorted together.** Plan steps used the + genuine `started_at`; tool calls used the synthetic value; the final + sort mixed them. Steps with no `started_at` fell back to `now` — **97 of + 339 non-pending steps in the DB (29%) had `started_at = NULL`** — so they + landed at the bottom of the timeline regardless of when they ran. + +The real data already existed and was already served: `agent_activity` +holds true `ts`, `duration_ms`, `success`, and +`correlation_id = session_id`, exposed at `GET /agent-activity`. The panel +ignored it and reconstructed a worse version from the message blob. + +### Fix (implemented — fix 1 + 2) + +1. **Carry real timestamps on tool calls.** `computeActivityLog` uses each + tool call's message `created_at` (a true persisted time). The + `now - (len - mi) * 1000` expression is gone entirely. +2. **Only fall back to wall-clock for genuinely-live entries, and freeze + it once assigned** — a `Map` outside the derivation, so + re-deriving never moves an existing entry. This is what kills the churn. + +Deferred to a later pass: backing the panel with `agent_activity` for +historical sessions (fix 3, unlocks `duration_ms`) — the two reported +symptoms (wrong clock, churn) no longer reproduce without it. + +--- + +## P1.1 — Plan-step events for a superseded generation were silently dropped + +The frontend half of P0.1, and the reason the panel *froze* rather than +merely showing wrong steps. + +On `plan.proposed` with `appended: false`, the store replaced its step +list wholesale — so after the re-plan it held seq 7–12. Every subsequent +`plan.step.started` / `plan.step.finished` carried seq 1–5 and a gen-1 +`step_id`, and `applyPlanStepEventTo` bailed on no match: + +```ts +if (i === -1) return steps +``` + +So for the entire second half of `398f5eda` — the half where all the real +work happened — **the panel showed six pending steps and nothing ever +moved.** Then `completeTask` closed them in the DB while emitting only +`task.status`, no per-step events, so they stayed pending on screen even +after the session finished. + +### Fix (implemented) + +- Fixing P0.1 removed the cause (the events now carry the correct + generation-relative seq + the panel's current steps match). The `i === -1` + branch now `console.warn`s and increments an exported + `droppedPlanStepEvents` counter instead of returning silently, so the + next divergence is visible instead of looking like a dead UI. +- **`completeTask`'s auto-close sweep now emits `plan.step.finished` per + closed step** (scoped to the current generation). General rule enforced: + no plan-step status change without a corresponding event. + +--- + +## P1.2 — Every plan carried a duplicate writeback step + +In `398f5eda` gen 2, step 11 was the model's own writeback step and step 12 +was the auto-appended one. The detector substring-matched the literal tool +names `update_entity_attributes` / `create_relationship` in the title or +detail; the model wrote a natural-language equivalent, so the match failed +and a redundant step was appended. Same pattern in `0a49ba3d` and +`9368633d`. + +### Fix (implemented) + +Broadened the detector to a case-insensitive check for `write back` / +`writeback` / `upsert_knowledge` in the title or detail, on top of the +existing tool-name match. + +--- + +## P2.1 — Long unexplained stalls, invisible in the UI *(deferred)* + +- `bad26076`: a greeting took **16 minutes** wall-clock with 6 activity rows. +- `2065a29a`: step 1 showed `started_at` → `finished_at` spanning **16 minutes** + for a `sensors` call that returned in milliseconds. + +The work took under a second; the step was *open* for 16 minutes. The panel +has no way to distinguish "working" from "waiting for a nudge." Surfaces a +step's idle time: mark a `running` step *stalled* when it has had no +`agent_activity` row for >60s. Deferred — needs the `agent_activity`-backed +panel (P0.2 fix 3). + +## P2.2 — `agent_activity` is a single-type table *(deferred — decision)* + +All rows are `activity_type = 'tool_call'`. Either start emitting the other +types the schema anticipates (`reasoning`, `plan`, `error`) or drop the +dimension. Worth a decision, not urgent. + +--- + +## Recommended sequence (executed) + +| Order | Item | Status | +|---|---|---| +| 1 | P0.1 fix 3 + 4 (refuse superseded writes, filter on read) | done | +| 2 | P0.2 fix 1 + 2 (real timestamps, frozen fallback) | done | +| 3 | P1.1 (emit events from the auto-close sweep) | done | +| 4 | P0.1 fix 2 (generation-relative seq) + migration | done | +| 5 | P1.2, P2.1 | P1.2 done; P2.1 deferred | +| 6 | P0.2 fix 3 (back the panel with `agent_activity`) | deferred | +| 7 | P2.2 | deferred | + +## Regression coverage (added) + +- `store_test.go`: `TestUpdatePlanStep_GenerationRelative` — re-plan → + `update_plan_step(seq=1)` must address gen-2 and never resurrect a + superseded gen-1 `replaced` row; out-of-range seq → `errPlanStepNotFound`. +- `store_test.go`: `TestCompleteTask_AutoCloseEmitsEvents` — auto-close + emits one `plan.step.finished` per closed step and stamps `started_at`. +- `store_test.go`: `TestProposePlan_RefuseInFlight` — updated for + generation-relative seq + `?all=true`. +- `web/src/lib/stores/activity.test.ts`: `computeActivityLog` is pure w.r.t. + wall-clock (two calls 50ms apart → identical output), persisted tool calls + use real `created_at`, live entries freeze instead of churning. + +--- + +## Resolution (2026-08-03) + +Shipped in commit `467589d` (VERSION `0.14.0` → `0.14.1`), pushed to +`origin/main`, deployed via the Gitea webhook (`scripts/deploy.sh`): +pg_dump → pull → `docker compose build` → `up -d` → health check (healthy). + +Verification on the bug-report session `398f5eda` post-migration: + +``` +gen 1: seq 1..6 (the abandoned "force 1Gbps" plan — superseded) +gen 2: seq 1..6 (the real EEE work — was seq 7..12, now normalized to 1..6) +``` + +- `schema_migrations` v29 applied; old `idx_plan_steps_session` dropped, + unique `idx_plan_steps_session_gen_seq` in place. +- Containers recreated; `healthz` and `/agent/sessions/:id/plan` HTTP 200. +- Full `cmd/nomos` suite (23 tests) + web suite (70 tests) green; `go vet` + clean; ESLint/Prettier clean. + +Note: historical `started_at = NULL` on already-completed steps (visible on +`398f5eda` gen 2) is left as-is — backfilling would fabricate times. Going +forward `completeTask` stamps `started_at`, and the frontend freezes +NULL-started steps stably so they no longer churn.