Judge a walk's machine on its last send, enter a resumed tier anew, and resume a walk lost to silence (issue 1886)

R4e, resumed at tier 1 after a stop of five hours, named ace and shanks silent within seconds of tier 1's send: the
walk judged each machine on every send it had made it, tier 0's of 00:23 too, held against tier 1's templates, and
measured the bound from it. A send carries the whole declaration, so the last one is what a machine is judged on.
The resume kept the tier's entry of before the stop, so the plan read waiting for 5h48m. And plans retry refused a
walk failed only by the gate's silence, though its machines had since applied.
This commit is contained in:
2026-10-23 08:02:11 +02:00
parent 219fdcd7f0
commit b7d996878b
5 changed files with 299 additions and 28 deletions
+71
View File
@@ -218,6 +218,15 @@ func retryRefusal(p inventory.Plan, plans []inventory.Plan, onPath map[string]st
} }
return oneWalkAtATime(p, plans, onPath) return oneWalkAtATime(p, plans, onPath)
} }
// **A walk lost to silence is resumed** (issue 1886): its tier was sent whole and only the gate after it failed it, every
// machine it waited on silent; once they reported, it goes on from that gate.
if len(stopped) == 0 && lostToSilence(p) {
if q, found := newerOpenPlan(p, plans); found {
return fmt.Errorf("%s supersedes it: a newer merge of %s (%s at %s) is open, and resuming %s would send "+
"what that one replaced", q.ID, q.Repository, q.ID, short(q.Commit), p.ID)
}
return oneWalkAtATime(p, plans, onPath)
}
if len(stopped) == 0 { if len(stopped) == 0 {
return fmt.Errorf("nothing in tier %d of %s failed to build or stopped rolling out — it stopped at: %s", return fmt.Errorf("nothing in tier %d of %s failed to build or stopped rolling out — it stopped at: %s",
p.Tier, p.ID, p.Note) p.Tier, p.ID, p.Note)
@@ -412,6 +421,20 @@ func retryPlan(ctx context.Context, open *stores, id string) (string, error) {
} }
return said, nil return said, nil
} }
if len(failed) == 0 && lostToSilence(p) {
reports, err := inv.LastReports(ctx)
if err != nil {
return "", err
}
said, err := resumeLost(&p, silentNodes(p, reports, time.Now().UTC(), provLookup(ctx)))
if err != nil {
return "", err
}
if err := inv.SavePlan(ctx, &p); err != nil {
return "", err
}
return said, nil
}
if len(failed) == 0 { if len(failed) == 0 {
return retryRollouts(ctx, open, &p) return retryRollouts(ctx, open, &p)
} }
@@ -693,3 +716,51 @@ func resumeStopped(p *inventory.Plan) string {
return fmt.Sprintf("%s resumed at tier %d of %d, stopped by %s: %s; this verb asks nothing — the next look carries it "+ return fmt.Sprintf("%s resumed at tier %d of %d, stopped by %s: %s; this verb asks nothing — the next look carries it "+
"on as any walk", p.ID, p.Tier+1, len(p.Tiers), by, waits) "on as any walk", p.ID, p.Tier+1, len(p.Tiers), by, waits)
} }
// silentGateWords say, in a plan's note, that the gate between two tiers found every machine it waits on silent past
// ApplySilentAfter, and failed the plan as lost (issue 1160): one text for the writer and the reader (lostToSilence).
const silentGateWords = "every machine it waits on said nothing on its send within"
// lostToSilence is whether a plan failed only at the gate after its tier, every machine it waited on silent (issue
// 1886): nothing in its tier failed to build, stopped rolling out or is still to ask — the look had sent the whole tier.
func lostToSilence(p inventory.Plan) bool {
if p.State != inventory.PlanFailed || p.Tier >= len(p.Tiers) || !strings.Contains(p.Note, silentGateWords) ||
len(failedIn(p)) > 0 || len(stoppedRollouts(p)) > 0 {
return false
}
asked, _, unasked := waitingIn(p)
return asked == 0 && unasked == 0
}
// resumeLost sets a walk lost to silence building again at the tier it failed after (issue 1886), for the next look to
// judge its gate again on the machines' reports, unless every machine its tier was sent to is still silent: then
// nothing it needs is delivered anywhere yet, and the retry is refused as the gate would fail it again.
func resumeLost(p *inventory.Plan, silent map[string]bool) (string, error) {
var sent, still []string
for _, m := range p.Tiers[p.Tier] {
if s := p.Modules[m]; s != nil {
for n := range s.Rest {
if !slices.Contains(sent, n) {
sent = append(sent, n)
}
}
}
}
for _, n := range sent {
if silent[n] {
still = append(still, n)
}
}
sort.Strings(still)
if len(sent) > 0 && len(still) == len(sent) {
return "", fmt.Errorf("%s failed because every machine its tier %d waits on said nothing on its send, and %s "+
"still said nothing: retry once it reported", p.ID, p.Tier+1, strings.Join(still, ", "))
}
was := p.Note
p.State = inventory.PlanBuilding
goesOnAgain(p)
p.Note = fmt.Sprintf("tier %d resumed by hand after it failed as lost (%s): its gate is judged again on the "+
"machines' reports", p.Tier, was)
return fmt.Sprintf("%s resumed at tier %d of %d, failed as lost to silence (%s); this verb asks and sends nothing — "+
"the next look judges its gate again and carries it on as any walk", p.ID, p.Tier+1, len(p.Tiers), was), nil
}
+39 -28
View File
@@ -1457,8 +1457,7 @@ func advanceOnce(ctx context.Context, open *stores, p *inventory.Plan,
// Every machine the next tier waits on is silent: nothing it needs was delivered anywhere, so the plan does // Every machine the next tier waits on is silent: nothing it needs was delivered anywhere, so the plan does
// not go on as if it had been (issue 1160). // not go on as if it had been (issue 1160).
p.State = inventory.PlanFailed p.State = inventory.PlanFailed
p.Note = fmt.Sprintf("tier %d built; every machine it waits on said nothing on its send within %s: %s", p.Note = fmt.Sprintf("tier %d built; %s %s: %s", p.Tier, silentGateWords, applySilentAfter, strings.Join(quiet, ", "))
p.Tier, applySilentAfter, strings.Join(quiet, ", "))
fmt.Printf("%s: %s\n", p.ID, p.Note) fmt.Printf("%s: %s\n", p.ID, p.Note)
return true, nil return true, nil
} }
@@ -1543,50 +1542,62 @@ func walkReports(p inventory.Plan, reports []inventory.Reported, now time.Time,
carried[node] = append(carried[node], m) carried[node] = append(carried[node], m)
} }
} }
seen := map[string]bool{} // **Each machine on the walk's last send to it** (issue 1886): a send carries the machine's whole declaration (ADR
// 0221), so a report on the last one answers every earlier one, and the bound runs from it. Judged on every send
// it had made, a walk whose tiers were sent hours apart — R4e, stopped at tier 1 and resumed — held tier 0's send of
// 00:23 against tier 1's templates and named its machines silent 35 seconds after tier 1 was sent.
last := map[string]inventory.SentDeclaration{}
lastAt := map[string]time.Time{}
for _, s := range p.Modules { for _, s := range p.Modules {
if s == nil { if s == nil {
continue continue
} }
for node, sent := range s.Rest { for node, sent := range s.Rest {
sent = sent.Only(carried[node]...)
if seen[node] {
continue
}
r := byNode[node]
at := sent.At at := sent.At
if at.IsZero() && s.SentAt != nil { if at.IsZero() && s.SentAt != nil {
at = *s.SentAt at = *s.SentAt
} }
// A module handed to the provisioner is applied only once its client said so too (ADR 0362 §1-5). was, ok := last[node]
outcome, reported := provisionedOutcome(node, sent, r, r.At != nil && sent.ReportsOn(r), prov) if !ok || laterSend(sent, at, was, lastAt[node]) {
switch { last[node], lastAt[node] = sent, at
case reported:
seen[node] = true
switch {
case outcome == inventory.OutcomeFailed || outcome == inventory.OutcomeRefused:
failed = append(failed, node)
case strings.HasPrefix(outcome, inventory.OutcomeProvisioningFailed):
failed = append(failed, node+" ("+outcome+")")
}
case !at.IsZero() && now.Sub(at) > applySilentAfter:
seen[node] = true
silent = append(silent, node)
default:
if !slices.Contains(waiting, node) {
waiting = append(waiting, node)
}
} }
} }
} }
// A machine one module's send was reported on and another's not yet is the same send: reported. for node, sent := range last {
waiting = slices.DeleteFunc(waiting, func(n string) bool { return seen[n] }) at := lastAt[node]
sent = sent.Only(carried[node]...)
r := byNode[node]
// A module handed to the provisioner is applied only once its client said so too (ADR 0362 §1-5).
outcome, reported := provisionedOutcome(node, sent, r, r.At != nil && sent.ReportsOn(r), prov)
switch {
case reported:
switch {
case outcome == inventory.OutcomeFailed || outcome == inventory.OutcomeRefused:
failed = append(failed, node)
case strings.HasPrefix(outcome, inventory.OutcomeProvisioningFailed):
failed = append(failed, node+" ("+outcome+")")
}
case !at.IsZero() && now.Sub(at) > applySilentAfter:
silent = append(silent, node)
default:
waiting = append(waiting, node)
}
}
sort.Strings(waiting) sort.Strings(waiting)
sort.Strings(failed) sort.Strings(failed)
sort.Strings(silent) sort.Strings(silent)
return waiting, failed, silent return waiting, failed, silent
} }
// laterSend is whether a, sent at aAt, is a later send to a machine than b, sent at bAt: by its sequence when both carry
// one, else by when it went.
func laterSend(a inventory.SentDeclaration, aAt time.Time, b inventory.SentDeclaration, bAt time.Time) bool {
if a.Sequence > 0 && b.Sequence > 0 && a.Sequence != b.Sequence {
return a.Sequence > b.Sequence
}
return aAt.After(bAt)
}
// restOf is, for one module, every machine of its rest that the send reached and what it carried there. // restOf is, for one module, every machine of its rest that the send reached and what it carried there.
func restOf(to, sent []string, what map[string]inventory.SentDeclaration) map[string]inventory.SentDeclaration { func restOf(to, sent []string, what map[string]inventory.SentDeclaration) map[string]inventory.SentDeclaration {
out := map[string]inventory.SentDeclaration{} out := map[string]inventory.SentDeclaration{}
@@ -0,0 +1,151 @@
package main
import (
"slices"
"strings"
"testing"
"time"
"github.com/novox/mesh-controller/internal/inventory"
)
// Issue 1886, the resume of R4e (plan-1792707174627079192): tier 0 was sent at 00:23:28, the walk was stopped at
// 02:01 and resumed at 07:43, and tier 1 was sent at 07:49:54. 35 seconds later the gate named ace silent "within
// 15m0s", and at 07:51:30 shanks, in the same second shanks reported it applied: the plan failed as lost. The walk
// judged each machine on every send it had made it, tier 0's of 00:23 too, narrowed to every module the walk carried
// there — so tier 0's send was held against the templates of tier 1's modules it never carried, and silence was
// measured from 00:23. A machine is judged on the walk's last send to it: that send carries its whole declaration.
func r4eResumed() (inventory.Plan, []inventory.Reported, inventory.ProvLookup, time.Time) {
tier0 := time.Date(2026, 10, 22, 22, 23, 28, 0, time.UTC)
tier1 := time.Date(2026, 10, 23, 5, 49, 54, 0, time.UTC)
now := time.Date(2026, 10, 23, 5, 51, 30, 0, time.UTC)
t0, t1 := tier0, tier1
p := inventory.Plan{ID: "plan-1792707174627079192", State: inventory.PlanRolling, Tier: 1,
Tiers: [][]string{{"pacman"}, {"mesh-build-image"}, {"gitea"}},
Modules: map[string]*inventory.PlanModule{
"pacman": {State: "built", SentAt: &t0, Rest: map[string]inventory.SentDeclaration{
"shanks": {Digest: "d0-shanks", Sequence: 900, At: tier0,
Provisioned: map[string]string{"pacman": "pac-1", "mesh-build-image": "img-old"}},
"ace": {Digest: "d0-ace", Sequence: 1100, At: tier0,
Provisioned: map[string]string{"pacman": "pac-1", "mesh-build-image": "img-old"}}}},
"mesh-build-image": {State: "built", SentAt: &t1, Rest: map[string]inventory.SentDeclaration{
"shanks": {Digest: "d1-shanks", Sequence: 971, At: tier1,
Provisioned: map[string]string{"pacman": "pac-1", "mesh-build-image": "img-new"}},
"ace": {Digest: "d1-ace", Sequence: 1212, At: tier1,
Provisioned: map[string]string{"pacman": "pac-1", "mesh-build-image": "img-new"}}}},
"gitea": {}}}
shanksAt := now
aceAt := time.Date(2026, 10, 23, 0, 57, 50, 0, time.UTC)
reports := []inventory.Reported{
// shanks reported on tier 1's send in the second the gate looked.
{Node: "shanks", Outcome: inventory.OutcomeApplied, At: &shanksAt, Declared: "d1-shanks", Current: true,
ReportedSequence: 971},
// ace's last report is from before tier 1's send, on a declaration sequenced after tier 0's.
{Node: "ace", Outcome: inventory.OutcomeApplied, At: &aceAt, Declared: "d-ace-0257", ReportedSequence: 1150},
}
says := map[string]inventory.ProvReport{
"shanks/pacman": {Status: inventory.ProvApplied, Templates: "pac-1", At: now},
"shanks/mesh-build-image": {Status: inventory.ProvApplied, Templates: "img-new", At: now},
"ace/pacman": {Status: inventory.ProvApplied, Templates: "pac-1", At: aceAt},
// ace's client had not placed the old image's files (issue 1884), and has not yet the new one's.
"ace/mesh-build-image": {Status: inventory.ProvWaiting, Templates: "img-old", At: aceAt},
}
prov := func(node, module string) (inventory.ProvReport, bool) { r, ok := says[node+"/"+module]; return r, ok }
return p, reports, prov, now
}
func TestAResumedWalkJudgesEachMachineOnItsLastSend(t *testing.T) {
p, reports, prov, now := r4eResumed()
waiting, failed, silent := walkReports(p, reports, now, prov)
if len(silent) != 0 {
t.Fatalf("1886: %v named silent within %s of tier 1's send, from tier 0's send of 00:23", silent, applySilentAfter)
}
if len(failed) != 0 || !slices.Equal(waiting, []string{"ace"}) {
t.Fatalf("1886: waiting %v, failed %v; want ace waited for (sent 96 s ago) and shanks reported", waiting, failed)
}
// The gate the plan failed at: mesh-build-image runs on ace and shanks, which tier 2 needs.
needs := []gateNeed{{module: "mesh-build-image", running: []string{"ace", "shanks"},
since: func(string) time.Time { return *p.Modules["mesh-build-image"].SentAt }}}
w, quiet, lost := settleTierGate(needs, reports, silentNodes(p, reports, now, prov))
if lost || len(quiet) != 0 || !slices.Equal(w, []string{"mesh-build-image on ace"}) {
t.Fatalf("1886: the gate says waiting %v, silent %v, lost %v; want mesh-build-image on ace waited for", w, quiet, lost)
}
}
// The machine silent on the walk's last send to it is still silent once the bound has passed since that send.
func TestAMachineSilentOnItsLastSendIsStillSilent(t *testing.T) {
p, reports, prov, now := r4eResumed()
later := now.Add(applySilentAfter + time.Minute)
_, _, silent := walkReports(p, reports, later, prov)
if !slices.Equal(silent, []string{"ace"}) {
t.Fatalf("1886: silent %v past the bound from tier 1's send; want ace", silent)
}
}
// A walk failed only because every machine its gate waited on was silent, whose tiers are all sent, is carried on by
// `plans retry` once those machines reported (issue 1886): it failed on no build and no rollout, so the retry of failed
// builds and of stopped rollouts refused it with "nothing in tier 1 … failed to build or stopped rolling out".
func r4eLost() inventory.Plan {
p, _, _, _ := r4eResumed()
p.State = inventory.PlanFailed
p.Note = "tier 1 built; " + silentGateWords + " 15m0s: shanks"
// mesh-tools is built and recorded, never sent, as R4e's was.
p.Tiers[1] = append(p.Tiers[1], "mesh-tools")
p.Modules["mesh-tools"] = &inventory.PlanModule{State: "built"}
return p
}
func TestRetryCarriesOnAWalkLostToSilenceOnceItsMachinesReported(t *testing.T) {
p, reports, prov, now := r4eResumed()
p = r4eLost()
if !lostToSilence(p) {
t.Fatalf("1886: the plan R4e failed as is not read as lost to silence: %q", p.Note)
}
if err := retryRefusal(p, []inventory.Plan{p}, ownPathOf(nil)); err != nil {
t.Fatalf("1886: a walk lost to silence was refused a retry: %v", err)
}
reports[1].Current, reports[1].Declared, reports[1].ReportedSequence = true, "d1-ace", 1212
reports[1].At = &now
says := map[string]inventory.ProvReport{}
for _, n := range []string{"ace", "shanks"} {
says[n+"/pacman"] = inventory.ProvReport{Status: inventory.ProvApplied, Templates: "pac-1", At: now}
says[n+"/mesh-build-image"] = inventory.ProvReport{Status: inventory.ProvApplied, Templates: "img-new", At: now}
}
prov = func(node, module string) (inventory.ProvReport, bool) { r, ok := says[node+"/"+module]; return r, ok }
said, err := resumeLost(&p, silentNodes(p, reports, now.Add(time.Hour), prov))
if err != nil {
t.Fatalf("1886: the resume of a walk whose machines reported refused: %v", err)
}
if p.State != inventory.PlanBuilding || p.Tier != 1 {
t.Fatalf("1886: resumed walk is %s at tier %d; want building at tier 1, for the next look to pass its gate", p.State, p.Tier)
}
if !strings.Contains(p.Note, "resumed by hand") || !strings.Contains(said, "resumed at tier 2 of 3") {
t.Fatalf("1886: note %q, said %q", p.Note, said)
}
}
// Every machine its tier was sent to still silent: the gate would fail it again, so the retry says so instead.
func TestRetryRefusesAWalkLostToSilenceWhileEveryMachineIsStillSilent(t *testing.T) {
p := r4eLost()
if _, err := resumeLost(&p, map[string]bool{"ace": true, "shanks": true}); err == nil || !strings.Contains(err.Error(), "ace, shanks") {
t.Fatalf("1886: a walk whose machine is still silent was resumed: %v", err)
}
if p.State != inventory.PlanFailed {
t.Fatalf("1886: a refused resume changed the plan to %s", p.State)
}
}
// A walk lost to silence with something of its tier never sent is not this: its send is the look's to make.
func TestALostWalkWithATierUnsentIsNotLostToSilence(t *testing.T) {
p := r4eLost()
p.Modules["mesh-build-image"].State = "asked"
if lostToSilence(p) {
t.Fatal("1886: a tier with a module still asked was read as lost to silence")
}
p = r4eLost()
p.Note = "tier 1 built; mesh-build-image failed to build"
if lostToSilence(p) {
t.Fatal("1886: a plan failed by a build was read as lost to silence")
}
}
+6
View File
@@ -675,6 +675,12 @@ func tierLeftOf(old *Plan, p Plan, now time.Time) (time.Time, *Duration) {
since = old.Created since = old.Created
} }
wasOpen := old.State == PlanBuilding || old.State == PlanRolling wasOpen := old.State == PlanBuilding || old.State == PlanRolling
if !wasOpen && p.Open() {
// **A walk set open again enters its tier anew** (issue 1886): a resume or a retry at the tier it ended at. Kept,
// the entry of before its stop measured the tier from hours before the resume — R4e read "waiting … for 5h48m53s"
// seven minutes after it was resumed — and the watchdog of its progress (S3) found it late at once.
return now, nil
}
if !wasOpen || (old.Tier == p.Tier && p.Open()) { if !wasOpen || (old.Tier == p.Tier && p.Open()) {
return since, nil // still in the tier, or already ended return since, nil // still in the tier, or already ended
} }
@@ -0,0 +1,32 @@
package inventory
import (
"testing"
"time"
)
// Issue 1886: R4e entered tier 1 at 02:01, was stopped, and was resumed at 07:43 at the same tier. Its save kept the
// tier's entry of 02:01, so at 07:50 the plan read "waiting for mesh-build-image on shanks to be applied for 5h48m53s"
// and its progress watchdog measured the tier from before the stop. A walk set open again at the tier it ended at
// enters that tier anew: its time in the tier runs from the resume.
func TestAWalkResumedAtItsTierEntersItAnew(t *testing.T) {
entered := time.Date(2026, 10, 23, 0, 1, 7, 0, time.UTC)
resumed := time.Date(2026, 10, 23, 5, 43, 30, 0, time.UTC)
old := &Plan{ID: "plan-r4e", State: PlanFailed, Tier: 1, Tiers: [][]string{{"a"}, {"b"}, {"c"}},
Created: entered.Add(-2 * time.Hour), TierEntered: entered}
p := *old
p.State = PlanBuilding
got, d := tierLeftOf(old, p, resumed)
if !got.Equal(resumed) || d != nil {
t.Fatalf("1886: a walk resumed at tier 1 entered it at %s (duration %v); want %s, no tier left", got, d, resumed)
}
// A walk still in its tier keeps its entry; one that ended keeps it too.
open := *old
open.State = PlanRolling
if got, _ := tierLeftOf(&open, open, resumed); !got.Equal(entered) {
t.Fatalf("an open walk still in its tier was stamped anew: %s", got)
}
if got, _ := tierLeftOf(old, *old, resumed); !got.Equal(entered) {
t.Fatalf("a failed walk saved again was stamped anew: %s", got)
}
}