From fcaad7271a8cf0cfcf55f0d9fa79c538697beb5b Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 21 Sep 2026 17:43:24 +0200 Subject: [PATCH] A failure that repeats is said to be stuck MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The mesh kept one report per machine, replaced, so a resource nothing can ever apply looked like a failure that had just happened, every reconcile interval, for ever. The row now keeps when the current failure began and how many reports in a row have said it — the same outcome, refusal and failed resources; anything different starts again and a clean apply clears it. Three make the machine stuck, and status says so beside the failure, in words and in JSON (novox/hq 04-ISSUES/065, ADR 0090). --- cmd/mesh-controller/readable.go | 6 ++ cmd/mesh-controller/readable_test.go | 28 +++++++ cmd/mesh-controller/status.go | 8 ++ internal/inventory/doing_test.go | 76 +++++++++++++++++++ ...ilure-that-repeats-is-said-to-be-stuck.sql | 15 ++++ internal/inventory/nodes.go | 58 ++++++++++++-- 6 files changed, 183 insertions(+), 8 deletions(-) create mode 100644 internal/inventory/migrations/0025-a-failure-that-repeats-is-said-to-be-stuck.sql diff --git a/cmd/mesh-controller/readable.go b/cmd/mesh-controller/readable.go index 68c8bc6..891bfcd 100644 --- a/cmd/mesh-controller/readable.go +++ b/cmd/mesh-controller/readable.go @@ -75,6 +75,11 @@ type machineDoing struct { } `json:"failed,omitempty"` Applied int `json:"applied"` At time.Time `json:"at"` + // Since is when this same failure was first reported and Times how many reports in a row + // have said it; Stuck is the mesh's word for "enough of them" (novox/hq 04-ISSUES/065). + Since *time.Time `json:"since,omitempty"` + Times int `json:"times"` + Stuck bool `json:"stuck"` } type machineReported struct { @@ -149,6 +154,7 @@ func statusAsJSON(asked answers) ([]byte, error) { for _, d := range wrong { row := machineDoing{ Node: d.Node, Outcome: d.Outcome, Refused: d.Refused, Applied: d.Applied, At: d.At, + Since: d.Since, Times: d.Times, Stuck: d.Stuck(), } for _, f := range d.Failed { row.Failed = append(row.Failed, struct { diff --git a/cmd/mesh-controller/readable_test.go b/cmd/mesh-controller/readable_test.go index fd7dedc..c9d07fa 100644 --- a/cmd/mesh-controller/readable_test.go +++ b/cmd/mesh-controller/readable_test.go @@ -139,3 +139,31 @@ func TestNoSecretIsInWhatABoardReads(t *testing.T) { } } } + +// A failure that has been reported identically enough times is said to be stuck, with when it +// began and how many times — so a board can tell a machine looping on something that will never +// apply from one that failed a minute ago (novox/hq 04-ISSUES/065, ADR 0090). +func TestAMachineFailingTheSameWayIsSaidToBeStuck(t *testing.T) { + began := time.Date(2026, 9, 21, 9, 0, 0, 0, time.UTC) + got := statusOf(t, + []inventory.Doing{ + {Node: "looping", Outcome: inventory.OutcomeFailed, Since: &began, Times: inventory.StuckAfter, + Failed: []inventory.FailedResource{{ID: "img", Error: "no such image"}}}, + {Node: "once", Outcome: inventory.OutcomeFailed, Since: &began, Times: 1, + Failed: []inventory.FailedResource{{ID: "img", Error: "no such image"}}}, + }, + []inventory.Node{{Name: "looping"}, {Name: "once"}}, nil, nil, nil) + + wrong, _ := got["wrong"].([]any) + looping, _ := wrong[0].(map[string]any) + if looping["stuck"] != true || looping["times"] != float64(inventory.StuckAfter) { + t.Fatalf("three identical failures are stuck: %v", looping) + } + if since, _ := looping["since"].(string); !strings.HasPrefix(since, "2026-09-21T09:00:00") { + t.Fatalf("when it began was not carried: %v", looping) + } + once, _ := wrong[1].(map[string]any) + if once["stuck"] != false || once["times"] != float64(1) { + t.Fatalf("one failure is not stuck: %v", once) + } +} diff --git a/cmd/mesh-controller/status.go b/cmd/mesh-controller/status.go index 2ebdd1f..cdc7bc7 100644 --- a/cmd/mesh-controller/status.go +++ b/cmd/mesh-controller/status.go @@ -99,6 +99,14 @@ func statusCommand(ctx context.Context, args []string) error { for _, f := range d.Failed { fmt.Printf(" %-18s %s: %s\n", "", f.ID, firstLine(f.Error)) } + if d.Stuck() { + // Said apart from the failure itself. The host's words say what is wrong; this + // says it is not new — the machine has applied, failed the same way and reported + // so this many times, and will keep doing exactly that until something changes + // (novox/hq 04-ISSUES/065). + fmt.Printf(" %-18s stuck: the same failure %d times since %s — it will not fix itself\n", + "", d.Times, d.Since.Local().Format("2006-01-02 15:04")) + } } fmt.Println() } diff --git a/internal/inventory/doing_test.go b/internal/inventory/doing_test.go index 6ba3f5e..e560fbb 100644 --- a/internal/inventory/doing_test.go +++ b/internal/inventory/doing_test.go @@ -245,3 +245,79 @@ func TestAMachineWithNothingComputedForItIsNotWaiting(t *testing.T) { t.Fatalf("a machine the caller could not work out was reported as waiting: %+v", waiting) } } + +// **A failure that repeats is told apart from one that just happened.** A node re-applies on a +// steady interval and reports each time, so a resource that will never apply arrives as the same +// report over and over — one row, replaced, "failed" at a fresh time — and nothing distinguished +// it from a failure that goes away by itself (novox/hq 04-ISSUES/065). The row now keeps when the +// current failure began and how many reports in a row have said it. +func TestTheSameFailureReportedAgainIsCountedNotRestarted(t *testing.T) { + inv := fresh(t) + ctx := context.Background() + id := nodeNamed(t, inv, "looping") + same := Doing{Outcome: OutcomeFailed, Failed: []FailedResource{{ID: "img", Error: "no such image"}}} + + if err := inv.RecordDoing(ctx, id, same); err != nil { + t.Fatal(err) + } + first, _, err := inv.DoingOf(ctx, "looping") + if err != nil { + t.Fatal(err) + } + if first.Times != 1 || first.Since == nil || first.Stuck() { + t.Fatalf("one failure is one failure, not yet stuck: %+v", first) + } + + for range StuckAfter - 1 { + if err := inv.RecordDoing(ctx, id, same); err != nil { + t.Fatal(err) + } + } + again, _, err := inv.DoingOf(ctx, "looping") + if err != nil { + t.Fatal(err) + } + if again.Times != StuckAfter || !again.Stuck() { + t.Fatalf("the same failure %d times is stuck: %+v", StuckAfter, again) + } + if !again.Since.Equal(*first.Since) { + t.Fatalf("the failure began at %s and the row now says %s", *first.Since, *again.Since) + } + + // A different failure is a new situation, not a longer one. + other := Doing{Outcome: OutcomeFailed, Failed: []FailedResource{{ID: "svc", Error: "unit not found"}}} + if err := inv.RecordDoing(ctx, id, other); err != nil { + t.Fatal(err) + } + changed, _, err := inv.DoingOf(ctx, "looping") + if err != nil { + t.Fatal(err) + } + if changed.Times != 1 || changed.Stuck() || !changed.Since.After(*first.Since) && !changed.Since.Equal(*first.Since) { + t.Fatalf("a new failure starts the count again: %+v", changed) + } + + // And a clean apply clears it: the machine is doing what it was told, since nothing. + if err := inv.RecordDoing(ctx, id, Doing{Outcome: OutcomeApplied, Applied: 2}); err != nil { + t.Fatal(err) + } + fine, _, err := inv.DoingOf(ctx, "looping") + if err != nil { + t.Fatal(err) + } + if fine.Times != 0 || fine.Since != nil || fine.Stuck() { + t.Fatalf("a machine doing what it was told is not stuck: %+v", fine) + } + + // The list of what is wrong carries the count, so `status` can say it. + if err := inv.RecordDoing(ctx, id, same); err != nil { + t.Fatal(err) + } + wrong, err := inv.NotDoingWhatTheyWereTold(ctx) + if err != nil { + t.Fatal(err) + } + if len(wrong) != 1 || wrong[0].Times != 1 || wrong[0].Since == nil { + t.Fatalf("got %+v", wrong) + } +} diff --git a/internal/inventory/migrations/0025-a-failure-that-repeats-is-said-to-be-stuck.sql b/internal/inventory/migrations/0025-a-failure-that-repeats-is-said-to-be-stuck.sql new file mode 100644 index 0000000..266ea5b --- /dev/null +++ b/internal/inventory/migrations/0025-a-failure-that-repeats-is-said-to-be-stuck.sql @@ -0,0 +1,15 @@ +-- A failure that repeats is told apart from one that just happened (novox/hq 04-ISSUES/065). +-- +-- A node re-applies what it holds on a steady interval and reports each time (novox/hq ADR 0010), +-- which is right for a failure that goes away by itself -- the overlay not up yet, a registry +-- briefly unreachable -- and makes a failure that will never go away look exactly the same: one +-- row, replaced, saying "failed" at a fresh time. Nothing distinguished "failed once, will succeed +-- when its dependency arrives" from "failed identically for ever", and nothing escalated the second. +-- +-- Still one row per node. What is added is how long the CURRENT failure has been the same one: +-- when it first appeared, and how many reports in a row have said it. A report that says something +-- different starts the count again; a clean apply clears it. + +alter table node_report + add column failing_since timestamptz, + add column failures int not null default 0; diff --git a/internal/inventory/nodes.go b/internal/inventory/nodes.go index ed6d60b..6729cb5 100644 --- a/internal/inventory/nodes.go +++ b/internal/inventory/nodes.go @@ -466,6 +466,15 @@ type Doing struct { // Declared is the digest of the declaration the report was about; empty when the machine // did not say. Declared string + + // Since is when the machine first reported THIS failure — the same outcome, the same refusal, + // the same failed resources — and Times is how many reports in a row have said it. A node + // re-applies on a steady interval and reports each time (novox/hq ADR 0010), so a failure + // that will never succeed arrives as the same report over and over, indistinguishable from + // one that just happened until somebody counts (novox/hq 04-ISSUES/065). Nil and zero for a + // machine doing what it was told. + Since *time.Time + Times int } // FailedResource is one thing a node could not do. @@ -477,23 +486,54 @@ type FailedResource struct { // Wrong reports whether this machine needs somebody to look at it. func (d Doing) Wrong() bool { return d.Outcome != OutcomeApplied } +// StuckAfter is how many identical reports in a row make a failure one that will not fix itself. +// +// Three, because a node reports after every apply and applies on its reconcile interval: one +// failure is an event, two may be the same event still under way, three separate applies saying +// the same words is a machine looping on something that is not going to change (novox/hq +// 04-ISSUES/065). Not a duration: a laptop that was shut for a week has had one attempt. +const StuckAfter = 3 + +// Stuck reports whether this machine has been failing the same way for long enough that waiting +// is no longer a plan. The failure is still the host's own words; this only says it is not new. +func (d Doing) Stuck() bool { return d.Wrong() && d.Times >= StuckAfter } + // RecordDoing keeps what a node said it did. // // One row per node, replaced. The question is the machine's current state — "this failed an hour // ago and then succeeded" is not something anybody needs to look at, and a table of every report // would bury the ones that matter. +// +// **What the row also keeps is whether this failure is the one before.** The same outcome, the +// same refusal, the same failed resources with the same words: then the failure did not just +// happen, it is still happening, and the row keeps when it began and counts one more report. Any +// difference starts again — a machine failing on a new resource is a new situation, not a longer +// one — and a clean apply clears both (novox/hq 04-ISSUES/065). func (i *Inventory) RecordDoing(ctx context.Context, node string, d Doing) error { failed, err := json.Marshal(d.Failed) if err != nil { return err } _, err = i.store.Pool().Exec(ctx, - `insert into node_report (node, outcome, refused, failed, applied, at, declared) - values ($1, $2, $3, $4, $5, now(), $6) + `insert into node_report (node, outcome, refused, failed, applied, at, declared, + failing_since, failures) + values ($1, $2, $3, $4, $5, now(), $6, + case when $2 <> $7 then now() end, + case when $2 <> $7 then 1 else 0 end) on conflict (node) do update set outcome = excluded.outcome, refused = excluded.refused, failed = excluded.failed, applied = excluded.applied, at = excluded.at, - declared = excluded.declared`, - node, d.Outcome, d.Refused, failed, d.Applied, d.Declared) + declared = excluded.declared, + failing_since = case + when excluded.outcome = $7 then null + when node_report.outcome = excluded.outcome and node_report.refused = excluded.refused + and node_report.failed = excluded.failed then node_report.failing_since + else excluded.at end, + failures = case + when excluded.outcome = $7 then 0 + when node_report.outcome = excluded.outcome and node_report.refused = excluded.refused + and node_report.failed = excluded.failed then node_report.failures + 1 + else 1 end`, + node, d.Outcome, d.Refused, failed, d.Applied, d.Declared, OutcomeApplied) return err } @@ -505,7 +545,7 @@ func (i *Inventory) RecordDoing(ctx context.Context, node string, d Doing) error // from. func (i *Inventory) NotDoingWhatTheyWereTold(ctx context.Context) ([]Doing, error) { rows, err := i.store.Pool().Query(ctx, - `select n.name, r.outcome, r.refused, r.failed, r.applied, r.at + `select n.name, r.outcome, r.refused, r.failed, r.applied, r.at, r.failing_since, r.failures from node_report r join node n on n.id = r.node where r.outcome <> $1 order by r.at desc`, OutcomeApplied) if err != nil { @@ -517,7 +557,8 @@ func (i *Inventory) NotDoingWhatTheyWereTold(ctx context.Context) ([]Doing, erro for rows.Next() { var d Doing var failed []byte - if err := rows.Scan(&d.Node, &d.Outcome, &d.Refused, &failed, &d.Applied, &d.At); err != nil { + if err := rows.Scan(&d.Node, &d.Outcome, &d.Refused, &failed, &d.Applied, &d.At, + &d.Since, &d.Times); err != nil { return nil, err } if err := json.Unmarshal(failed, &d.Failed); err != nil { @@ -537,8 +578,9 @@ func (i *Inventory) DoingOf(ctx context.Context, name string) (Doing, bool, erro var d Doing var failed []byte err = i.store.Pool().QueryRow(ctx, - `select outcome, refused, failed, applied, at from node_report where node = $1`, node.ID). - Scan(&d.Outcome, &d.Refused, &failed, &d.Applied, &d.At) + `select outcome, refused, failed, applied, at, failing_since, failures + from node_report where node = $1`, node.ID). + Scan(&d.Outcome, &d.Refused, &failed, &d.Applied, &d.At, &d.Since, &d.Times) if errors.Is(err, pgx.ErrNoRows) { return Doing{}, false, nil }