fix(nomos): generation-relative plan seq + real activity timestamps
The plan recorded false history after a re-plan and the activity panel showed fabricated, churning timestamps. Two bugs compounding on one event stream. Plan drift (P0.1): - proposePlan seq is now 1..N per generation; (session,generation,seq) is the addressing key. The model's 1-based update_plan_step calls always map to the CURRENT plan after a re-plan, instead of resurrecting a superseded `replaced` row as done while the live work went unrecorded. - updatePlanStep resolves against MAX(generation); a stale/out-of-range seq returns errPlanStepNotFound (never touches a superseded generation). - getPlanSteps returns only the current generation by default; ?all=true keeps the audit/eval view (plan_generations assertion). - completeTask auto-close scopes to the current gen, stamps started_at, and emits one plan.step.finished per closed step so the panel converges instead of freezing on "running" after completion (P1.1). - propose_plan result enumerates step seqs; writeback detector matches "write back"/"writeback"/"upsert_knowledge" so a natural-language final step isn't doubled (P1.2). - migration 029 renumbers existing seq per generation + unique index. Activity panel (P0.2 / P1.1, web): - computeActivityLog uses the real message created_at for tool calls; live entries fall back to wall-clock frozen on first sight, killing the 3s poll churn. Steps use real started_at. - dropped plan-step events warn + count instead of a silent no-op. Tests: TestProposePlan updated; + generation-relative-seq and auto-close event-emission regression tests; + web activity purity/timestamp tests. VERSION: 0.14.0 -> 0.14.1
This commit is contained in:
103
web/src/lib/stores/activity.test.ts
Normal file
103
web/src/lib/stores/activity.test.ts
Normal file
@@ -0,0 +1,103 @@
|
||||
import { describe, it, expect, vi } from 'vitest'
|
||||
import { writable } from 'svelte/store'
|
||||
|
||||
// computeActivityLog is a pure derivation; it only needs TYPES from the store
|
||||
// modules, so mock their runtime exports to keep the test isolated from the
|
||||
// real store graph (workspace.ts, e.g., starts a top-level setInterval).
|
||||
vi.mock('./chat', () => ({
|
||||
messages: writable([]),
|
||||
chatFor: vi.fn(() => ({
|
||||
messages: writable([]),
|
||||
streaming: writable(false),
|
||||
connectionState: writable('connected'),
|
||||
error: writable(null),
|
||||
notFound: writable(false)
|
||||
}))
|
||||
}))
|
||||
vi.mock('./workspace', () => ({
|
||||
planSteps: writable([]),
|
||||
currentTask: writable(null),
|
||||
workspaceFor: vi.fn(() => ({})),
|
||||
taskFor: vi.fn(() => writable(null))
|
||||
}))
|
||||
vi.mock('./execstream', () => ({
|
||||
liveExecutionOutputFor: vi.fn(() => writable(null))
|
||||
}))
|
||||
|
||||
import { computeActivityLog } from './activity'
|
||||
import type { ChatMessage } from './chat'
|
||||
import type { PlanStep, Session } from '$lib/api'
|
||||
|
||||
const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms))
|
||||
|
||||
function msg(partial: Partial<ChatMessage> & { id: string }): ChatMessage {
|
||||
return {
|
||||
id: partial.id,
|
||||
role: 'assistant',
|
||||
text: '',
|
||||
tools: partial.tools ?? [],
|
||||
pendingApprovals: [],
|
||||
created_at: partial.created_at
|
||||
}
|
||||
}
|
||||
|
||||
function toolResult(name: string, id: string): NonNullable<ChatMessage['tools']>[number] {
|
||||
return { type: 'tool_result', name, id, result: 'ok' }
|
||||
}
|
||||
|
||||
describe('computeActivityLog timestamps (P0.2)', () => {
|
||||
it('uses the message created_at for persisted tool calls, not a fabricated spread', () => {
|
||||
const created = '2026-07-29T20:08:10Z'
|
||||
const m = msg({
|
||||
id: 'm1',
|
||||
created_at: created,
|
||||
tools: [toolResult('get_entity', 't1'), toolResult('run', 't2')]
|
||||
})
|
||||
const entries = computeActivityLog([m], [], null, new Map())
|
||||
const want = new Date(created).getTime()
|
||||
for (const id of ['t1', 't2']) {
|
||||
const e = entries.find((x) => x.id === id)
|
||||
expect(e, `entry ${id} should exist`).toBeDefined()
|
||||
expect(e!.timestamp).toBe(want) // real time, shared per message — no now-(len-i)*1000
|
||||
}
|
||||
})
|
||||
|
||||
it('freezes live entries (no created_at) so re-derivation never churns them', async () => {
|
||||
const m = msg({ id: 'm1', tools: [toolResult('run', 't1')] }) // no created_at
|
||||
const frozen = new Map<string, number>()
|
||||
const a = computeActivityLog([m], [], null, frozen)
|
||||
const ts1 = a.find((e) => e.id === 't1')!.timestamp
|
||||
await sleep(60) // the 3s poller re-derives on a later tick
|
||||
const b = computeActivityLog([m], [], null, frozen)
|
||||
const ts2 = b.find((e) => e.id === 't1')!.timestamp
|
||||
expect(ts2).toBe(ts1) // frozen — the previous bug marched every entry forward
|
||||
})
|
||||
|
||||
it('is pure w.r.t. wall-clock: two calls with identical inputs give identical output', async () => {
|
||||
const created = '2026-07-29T20:08:10Z'
|
||||
const msgs = [
|
||||
msg({ id: 'm1', created_at: created, tools: [toolResult('get_entity', 't1')] }),
|
||||
msg({ id: 'm2', created_at: created, tools: [toolResult('run', 't2')] })
|
||||
]
|
||||
const steps: PlanStep[] = [
|
||||
{ id: 's1', seq: 1, title: 'A', detail: '', status: 'done', started_at: created }
|
||||
]
|
||||
const task = { id: 'sess', outcome: 'success', summary: 'done' } as unknown as Session
|
||||
const frozen = new Map<string, number>()
|
||||
const a = computeActivityLog(msgs, steps, task, frozen)
|
||||
await sleep(50)
|
||||
const b = computeActivityLog(msgs, steps, task, frozen)
|
||||
expect(b.map((e) => [e.id, e.timestamp, e.type])).toEqual(
|
||||
a.map((e) => [e.id, e.timestamp, e.type])
|
||||
)
|
||||
})
|
||||
|
||||
it('uses a step started_at instead of falling back to now', () => {
|
||||
const started = '2026-07-29T20:07:40Z'
|
||||
const steps: PlanStep[] = [
|
||||
{ id: 's1', seq: 1, title: 'A', detail: '', status: 'done', started_at: started }
|
||||
]
|
||||
const entries = computeActivityLog([], steps, null, new Map())
|
||||
expect(entries.find((e) => e.id === 's1')!.timestamp).toBe(new Date(started).getTime())
|
||||
})
|
||||
})
|
||||
@@ -58,13 +58,37 @@ function stringifyResult(result: unknown): string {
|
||||
// Pure derivation, parameterized so it can back both the global "current
|
||||
// session" activityLog below and a per-session activityLogFor(sessionId) for
|
||||
// a floating task window.
|
||||
function computeActivityLog(
|
||||
//
|
||||
// Timestamps are REAL where the data has them and FROZEN where it doesn't:
|
||||
// - persisted tool calls use their message's created_at (a true time);
|
||||
// - steps use their started_at when present;
|
||||
// - only genuinely-live entries (a tool call on the in-flight message that
|
||||
// has no created_at yet) fall back to wall-clock, and that value is frozen
|
||||
// into `frozen` on FIRST sight so a re-derive (the 3s poller re-sets
|
||||
// `messages` every tick) reads the same value instead of marching every
|
||||
// entry forward. Before this, every entry's time was
|
||||
// `now - (len - index) * 1000` — fabricated at render time and churning
|
||||
// every poll (P0.2). `frozen` is owned by the caller and lives across
|
||||
// re-derivations; pass a fresh Map for a purity test.
|
||||
export function computeActivityLog(
|
||||
$msgs: ChatMessage[],
|
||||
$steps: PlanStep[],
|
||||
$task: Session | null
|
||||
$task: Session | null,
|
||||
frozen: Map<string, number>
|
||||
): ActivityEntry[] {
|
||||
const entries: ActivityEntry[] = []
|
||||
const now = Date.now()
|
||||
// freeze: prefer a real persisted time; else reuse a value already pinned
|
||||
// for this id; else pin wall-clock now and remember it.
|
||||
const freeze = (id: string, real?: number | null): number => {
|
||||
if (real && real > 0) return real
|
||||
const hit = frozen.get(id)
|
||||
if (hit !== undefined) return hit
|
||||
frozen.set(id, now)
|
||||
return now
|
||||
}
|
||||
const tsOf = (iso?: string): number | undefined =>
|
||||
iso ? new Date(iso).getTime() || undefined : undefined
|
||||
|
||||
// Goal
|
||||
if ($task?.goal) {
|
||||
@@ -87,7 +111,7 @@ function computeActivityLog(
|
||||
s.status === 'running' ? 'step_running' : s.status === 'done' ? 'step_done' : 'step_failed',
|
||||
description: `Step ${s.seq}: ${stepLabel}`,
|
||||
detail: s.detail || undefined,
|
||||
timestamp: s.started_at ? new Date(s.started_at).getTime() : now,
|
||||
timestamp: freeze(s.id, tsOf(s.started_at)),
|
||||
status: s.status === 'running' ? 'running' : s.status === 'done' ? 'done' : 'failed'
|
||||
})
|
||||
}
|
||||
@@ -97,6 +121,7 @@ function computeActivityLog(
|
||||
let currentStepSeq = 0
|
||||
let entryIdx = 0
|
||||
for (let mi = 0; mi < $msgs.length; mi++) {
|
||||
const msgTs = tsOf($msgs[mi].created_at)
|
||||
for (const t of $msgs[mi].tools) {
|
||||
// Track current step from update_plan_step calls
|
||||
if (t.type === 'tool_use' && t.name === 'update_plan_step') {
|
||||
@@ -109,13 +134,14 @@ function computeActivityLog(
|
||||
|
||||
const label = toolActivityLabel(t)
|
||||
const stepTag = currentStepSeq > 0 ? currentStepSeq : undefined
|
||||
const id = t.id ?? `tool_${mi}_${entryIdx++}`
|
||||
if (t.type === 'tool_use') {
|
||||
entries.push({
|
||||
id: t.id ?? `tool_${mi}_${entryIdx++}`,
|
||||
id,
|
||||
type: 'tool_running',
|
||||
description: label,
|
||||
args: summarizeArgs(t.args),
|
||||
timestamp: now - ($msgs.length - mi) * 1000,
|
||||
timestamp: freeze(id, msgTs),
|
||||
toolName: t.name,
|
||||
stepSeq: stepTag,
|
||||
indent: stepTag != null,
|
||||
@@ -142,12 +168,12 @@ function computeActivityLog(
|
||||
// full entry itself. It used to fall back to the raw tool name
|
||||
// (e.g. "get_entity") instead of the humanized label here.
|
||||
entries.push({
|
||||
id: t.id ?? `tool_${mi}_${entryIdx++}`,
|
||||
id,
|
||||
type: t.error ? 'tool_error' : 'tool_done',
|
||||
description: t.error ? `${label}: ${t.error.slice(0, 80)}` : label,
|
||||
detail: t.error ? t.error : stringifyResult(t.result),
|
||||
args: summarizeArgs(t.args),
|
||||
timestamp: now - ($msgs.length - mi) * 1000,
|
||||
timestamp: freeze(id, msgTs),
|
||||
toolName: t.name,
|
||||
stepSeq: stepTag,
|
||||
indent: stepTag != null,
|
||||
@@ -160,14 +186,16 @@ function computeActivityLog(
|
||||
|
||||
// Knowledge recorded — detect from upsert_knowledge tool results
|
||||
for (let mi = 0; mi < $msgs.length; mi++) {
|
||||
const msgTs = tsOf($msgs[mi].created_at)
|
||||
for (const t of $msgs[mi].tools) {
|
||||
if (t.type === 'tool_result' && t.name === 'upsert_knowledge' && !t.error) {
|
||||
const title = typeof t.args?.title === 'string' ? t.args.title : ''
|
||||
const kid = `knowledge_${mi}_${t.id ?? ''}`
|
||||
entries.push({
|
||||
id: `knowledge_${mi}`,
|
||||
id: kid,
|
||||
type: 'knowledge',
|
||||
description: title ? `Recorded: ${title.slice(0, 60)}` : 'Recorded knowledge',
|
||||
timestamp: now - ($msgs.length - mi) * 1000,
|
||||
timestamp: freeze(kid, msgTs),
|
||||
status: 'done'
|
||||
})
|
||||
}
|
||||
@@ -180,7 +208,7 @@ function computeActivityLog(
|
||||
id: 'complete',
|
||||
type: 'complete',
|
||||
description: $task.summary || `Task ${$task.outcome}`,
|
||||
timestamp: now,
|
||||
timestamp: freeze('complete'),
|
||||
status: $task.outcome === 'failure' ? 'failed' : 'done'
|
||||
})
|
||||
}
|
||||
@@ -200,8 +228,13 @@ function computeActivityLog(
|
||||
return entries
|
||||
}
|
||||
|
||||
// A per-store freeze map: the first time a live entry (no real timestamp
|
||||
// yet) is seen, its wall-clock time is pinned here so the 3s poller's
|
||||
// re-derivation can't march it forward. Owned here, outside the derivation,
|
||||
// so it survives re-runs. The per-session path has its own Map keyed by id.
|
||||
const frozenTimestamps = new Map<string, number>()
|
||||
export const activityLog = derived([messages, planSteps, currentTask], ([$msgs, $steps, $task]) =>
|
||||
computeActivityLog($msgs, $steps, $task)
|
||||
computeActivityLog($msgs, $steps, $task, frozenTimestamps)
|
||||
)
|
||||
|
||||
// Attach streaming output to the `run` entry that is currently executing.
|
||||
@@ -222,13 +255,21 @@ function withLiveOutput(
|
||||
return entries
|
||||
}
|
||||
|
||||
// One freeze map per session window (entry ids are UUIDs, but the synthetic
|
||||
// 'goal'/'complete' ids collide across sessions, so each window keeps its own).
|
||||
const sessionFrozenTimestamps = new Map<string, Map<string, number>>()
|
||||
export function activityLogFor(sessionId: string): Readable<ActivityEntry[]> {
|
||||
const chat = chatFor(sessionId)
|
||||
const ws = workspaceFor(sessionId)
|
||||
const task = taskFor(sessionId)
|
||||
const live = liveExecutionOutputFor(sessionId)
|
||||
let frozen = sessionFrozenTimestamps.get(sessionId)
|
||||
if (!frozen) {
|
||||
frozen = new Map<string, number>()
|
||||
sessionFrozenTimestamps.set(sessionId, frozen)
|
||||
}
|
||||
return derived([chat.messages, ws.planSteps, task, live], ([$msgs, $steps, $task, $live]) =>
|
||||
withLiveOutput(computeActivityLog($msgs, $steps, $task), $live)
|
||||
withLiveOutput(computeActivityLog($msgs, $steps, $task, frozen), $live)
|
||||
)
|
||||
}
|
||||
|
||||
|
||||
@@ -93,12 +93,30 @@ function scheduleSessionsRefresh() {
|
||||
refreshTimer = setTimeout(() => loadSessions(), 300)
|
||||
}
|
||||
|
||||
// A dropped plan-step event is one that matched no step on screen —
|
||||
// historically a silent return, which made a disagreeing backend look like a
|
||||
// dead UI (the panel froze showing pending steps while work happened
|
||||
// elsewhere). Surface it so the next divergence is visible. Exported so a
|
||||
// debug surface (or a test) can read the count.
|
||||
export let droppedPlanStepEvents = 0
|
||||
export function resetDroppedPlanStepEvents(): void {
|
||||
droppedPlanStepEvents = 0
|
||||
}
|
||||
|
||||
function applyPlanStepEventTo(ws: WorkspaceState, data: PlanStepEventData) {
|
||||
const stepID = data?.step_id
|
||||
const seq = data?.seq
|
||||
ws.planSteps.update((steps) => {
|
||||
const i = steps.findIndex((s) => (stepID && s.id === stepID) || (seq != null && s.seq === seq))
|
||||
if (i === -1) return steps
|
||||
if (i === -1) {
|
||||
droppedPlanStepEvents++
|
||||
console.warn('plan step event matched no step on screen', {
|
||||
stepID,
|
||||
seq,
|
||||
status: data?.status
|
||||
})
|
||||
return steps
|
||||
}
|
||||
const next = [...steps]
|
||||
next[i] = {
|
||||
...next[i],
|
||||
|
||||
Reference in New Issue
Block a user