oikos/plans/done/2026-07-30-session-review-plan-drift-and-dead-activity-panel.md

# 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.