Merge pull request 'Issue 296: a plan's clock restarted at every save' (#175) from issues/296-a-plans-clock-restarted-at-every-save into main

This commit was merged in pull request #175.
This commit is contained in:
2026-10-07 19:04:58 +00:00
2 changed files with 99 additions and 0 deletions
@@ -0,0 +1,43 @@
---
status: located
opened: 2026-10-07
located-in: [mesh-controller cmd/mesh-controller (release_plan.go, watchdogs.go, status.go)]
fixed-by: mesh-controller PR #119
amended-design:
---
# 296. A plan's clock restarted at every save
## Symptom
On 2026-10-07 the controller's `plans` verb showed one plan for a merge to the catalogue repository
(commit `3ad22356`) as "tier 1 of 1, building for 1s". Read again over the next several minutes, it
said "building for 4s", then "building for 9s". The build had been requested at 19:48:41 and sat queued
for minutes. The line said it had only just started.
The same clock decides whether the line ends in " — LATE", and whether `status` counts the plan as
waiting past its bound. A plan whose clock goes back to zero every few seconds is never late. So
`plans` and `status` could not say that a plan was stuck. The design says a stuck plan is a warning
(to-be 45, S3).
## Where it lives
In the controller. The line counted from the plan's last save, not from when the plan entered its tier.
The plan was saved after every step the controller took on it, whether or not the step changed
anything. Those steps run on a 30-second timer and again after every build outcome anywhere on the
mesh. The trail is in [01-diagnosis.md](01-diagnosis.md).
## How it is checked
Two tests in the controller, each shown to fail on the commit before the fix:
- A plan saved three seconds ago that has been in its tier for forty minutes reads "building for 40m0s"
and LATE. LATE and the stalled condition agree on both sides of a measured bound.
- Against a real store, advancing a plan whose build is outstanding three times leaves its revision and
its last-save time where its last real change left them. Before the fix, its revision went from 3 to 6.
Live: during a plan whose tier waits on a queued build, `plans` counts up from when the tier was entered,
and the plan's revision does not move until something about it does.
At resolution this core issue names its replay, or says in `replay-none:` why none is possible
(ADR 0237).
@@ -0,0 +1,56 @@
# 296 — diagnosis
## 2026-10-07: the line's clock
The `plans` line for an open plan counted from the plan's `updated` column. The store sets that column
to the current time on every save. The same save also increments the plan's revision, which is used for
compare-and-set (to-be 45 §6). The " — LATE" marker compared this count against a fixed 30-minute bound.
The JSON from `status` did the same, and so did the count of late plans.
The watchdog that raises a plan's `stalled` condition (S3) counts differently. It starts from when the
plan entered its current tier, a time the save stamps only when the tier changes. Its bound comes from
the tier durations measured for the repository: three times their ninetieth percentile, and never less
than 30 minutes. So the watchdog and the line a person reads used different start times and could use
different bounds. The line was the one that was wrong.
The line for a walk waiting on its delivery's word had the same flaw. It said "for" the time since the
last save. The watchdog for that wait (S16) counts from when the walk was opened.
Ruled out: a clock difference between the machine running the verb and the store. The count was small
and kept growing again from zero, which only a column being rewritten explains.
## 2026-10-07: why a plan standing still was saved every few seconds
The controller moves plans forward in one loop. That loop runs on startup, every 30 seconds, and after
every build outcome on the mesh, from any plan or none. For each open plan it takes one step and then
saves the plan. It saved even when the step reported that nothing had moved. When a step failed, it
rewrote the same "tried again" note and saved that too.
A plan whose only module was asked and still queued at the build seat changes nothing on such a step.
The step reads the build records, finds no outcome, and returns. The save came anyway: a new `updated`
time, a new revision, and a `plan-moved` event on the bus (ADR 0239) about a plan that had not moved. On
a busy mesh, with outcomes arriving for other repositories' builds as well as the 30-second timer, that
meant a save every few seconds.
The same loop has a second form of this. A plan can have a step refused, for example because builds on
a machine are waiting for their own gate. When that happens, the loop logged the refusal and saved the
plan with the same "tried again" note on every tick. The controller's log showed one line, word for word
the same, every 30 seconds for each such plan.
The write was not needed. Nothing reads `updated` as a heartbeat, and the save is not what keeps a plan
alive. The tier stamp, the revision check and the build records do not depend on a save that changes
nothing.
## Fix (mesh-controller)
- The line, the `since` and `late` fields of `status --json`, and the count of late plans all start from
when the plan entered its tier. If the delivery let the walk go after that, they start from the go. A
walk still waiting for its delivery's word counts from when it was opened, as S16 does, and is never
called late. A plan read without the tier stamp falls back to its last save.
- LATE uses the bound the watchdog uses: the measured bound for the plan's repository, or the 30-minute
floor when nothing has been measured. The watchdog's start time and bound now come from the same two
functions, so the line and the condition cannot disagree about a plan.
- The loop compares the plan before and after each step and saves only when they differ. The fields the
store stamps itself are left out of that comparison.
- A refused step is logged and saved only when its note is new. The refusal's wording called the gated
walk a "release plan", a name the glossary retires; it now says "walk".