docs(plans): mark plan-drift & dead-activity-panel review done (467589d)
VERSION: 0.14.1 -> 0.14.2
This commit is contained in:
@@ -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<id, timestamp>` 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.
|
||||
Reference in New Issue
Block a user