diff --git a/cmd/mesh-controller/advisories_counted_test.go b/cmd/mesh-controller/advisories_counted_test.go new file mode 100644 index 00000000..f9914aa8 --- /dev/null +++ b/cmd/mesh-controller/advisories_counted_test.go @@ -0,0 +1,95 @@ +package main + +import ( + "strings" + "testing" + "time" + + "github.com/novox/mesh-controller/internal/conditions" + "github.com/novox/mesh-controller/internal/link" +) + +// **A refusal the bus said once is counted once** (novox/hq issue 402). The bus refused the controller +// one publish at 18:52:59 UTC on 2026-10-10 and never again, yet S9 looked at the one remembered +// advisory every half minute for the hour it is kept, and the condition said "observed 15 time(s), last +// 13s ago" with a refusal in its evidence every 30 seconds: two of us read it as a refusal going on and +// went looking for a missing grant. The condition counts what the bus said, with when it last said it, +// never how often the controller looked. +func TestARefusalSaidOnceIsCountedOnceHoweverOftenItIsLookedAt(t *testing.T) { + refused := time.Date(2026, 10, 10, 18, 52, 59, 0, time.UTC) + now := refused.Add(10 * time.Second) + store := conditions.NewInMemory() + k := conditions.NewKeeper(t.Context(), conditions.Options{Store: store, History: store, + Teller: &conditions.Told{}, Now: func() time.Time { return now }}) + t.Cleanup(func() { k.Close(t.Context()) }) + + // The words the live condition bus.controller.refused carried on 2026-10-10. + said := "the bus refused the controller: nats: permissions violation: Permissions Violation for " + + `Publish to "mesh.seat.mesh-delivery.tool.times"` + advisory := link.Advisory{Kind: link.AdvisoryRefused, ID: "controller", Said: said, + First: refused, Last: refused, Count: 1} + look := func() conditions.Condition { + t.Helper() + f := &signalFacts{now: now, host: "novox", advisories: []link.Advisory{advisory}} + if err := k.Reconcile(t.Context(), "S9", watchAdvisories(f)); err != nil { + t.Fatal(err) + } + c, found, err := conditions.ReadOne(t.Context(), store, "bus.controller.refused") + if err != nil || !found { + t.Fatalf("bus.controller.refused: found %v, %v", found, err) + } + return c + } + + var c conditions.Condition + for range 15 { + c = look() + now = now.Add(30 * time.Second) + } + if c.Observations != 1 || len(c.Evidence) != 1 { + t.Fatalf("one refusal, looked at 15 times, reads as observed %d time(s) with %d evidence lines: %+v", + c.Observations, len(c.Evidence), c.Evidence) + } + if !c.LastObserved.Equal(refused) || !c.Evidence[0].At.Equal(refused) { + t.Fatalf("last observed %s, evidence at %s: the refusal was at %s", c.LastObserved, c.Evidence[0].At, refused) + } + + // The bus refuses it three times more between two looks: the condition counts four refusals, says + // the newest, and adds one line of evidence for the look that saw them. + again := now.Add(-5 * time.Second) + advisory.Last, advisory.Count = again, 4 + c = look() + if c.Observations != 4 || len(c.Evidence) != 2 || !c.LastObserved.Equal(again) || !c.Evidence[0].At.Equal(again) { + t.Fatalf("four refusals read as observed %d time(s), last %s, evidence %+v", c.Observations, c.LastObserved, c.Evidence) + } + if !strings.Contains(c.Summary, "(4 times since 18:52 UTC)") { + t.Fatalf("summary %q", c.Summary) + } + now = now.Add(30 * time.Second) + if c = look(); c.Observations != 4 || len(c.Evidence) != 2 { + t.Fatalf("a look with nothing new counted: observed %d time(s), evidence %+v", c.Observations, c.Evidence) + } +} + +// **A condition that looks at the present still counts its looks** (novox/hq issue 402 changes only +// what reads a record): a machine silent for three looks was observed three times, and says so. +func TestAConditionOfThePresentCountsItsLooks(t *testing.T) { + now := time.Date(2026, 10, 10, 19, 0, 0, 0, time.UTC) + store := conditions.NewInMemory() + k := conditions.NewKeeper(t.Context(), conditions.Options{Store: store, History: store, + Teller: &conditions.Told{}, Now: func() time.Time { return now }}) + t.Cleanup(func() { k.Close(t.Context()) }) + var c conditions.Condition + for range 3 { + var err error + if c, err = k.Observe(t.Context(), conditions.Observation{Scope: conditions.ScopeMachine, ID: "ace", + Kind: "silent", Machine: "ace", Severity: conditions.Warning, Summary: "ace has not been heard from", + Source: "S1"}); err != nil { + t.Fatal(err) + } + now = now.Add(30 * time.Second) + } + if c.Observations != 3 || len(c.Evidence) != 3 || !c.LastObserved.Equal(now.Add(-30*time.Second)) { + t.Fatalf("observed %d time(s), %d evidence lines, last %s", c.Observations, len(c.Evidence), c.LastObserved) + } +} diff --git a/cmd/mesh-controller/signals.go b/cmd/mesh-controller/signals.go index c06190d9..620b3d8b 100644 --- a/cmd/mesh-controller/signals.go +++ b/cmd/mesh-controller/signals.go @@ -533,7 +533,10 @@ func watchAdvisories(f *signalFacts) []conditions.Observation { machine = f.host } o := conditions.Observation{Scope: conditions.ScopeBus, ID: a.ID, Kind: a.Kind, Token: a.Token, - Machine: machine, Severity: severity, Summary: a.Said + times, Said: a.Said} + Machine: machine, Severity: severity, Summary: a.Said + times, Said: a.Said, + // The advisory is remembered and read again on every look for an hour: the condition counts + // what the bus said and when, not the looks (novox/hq issue 402). + Happened: a.Last, Times: a.Count} if a.Kind == link.AdvisoryMaxDeliveries && a.Token == link.AdvisoryNotKept { o.Machine = consumerMachine(a.Stream, a.Consumer) o.Headline = clip(conditions.Capital(fmt.Sprintf("%s gave up on a message, not kept", diff --git a/internal/conditions/condition.go b/internal/conditions/condition.go index d8932dab..c30230cb 100644 --- a/internal/conditions/condition.go +++ b/internal/conditions/condition.go @@ -152,7 +152,9 @@ type Condition struct { // reopened after a send was there at the send unless the send fell in one of its gaps. First time.Time `json:"first,omitzero"` Gaps []Gap `json:"gaps,omitempty"` - // Observations is how many times it was observed since raised. + // Observations is how many times it was observed since raised: a look that sees it, for a source + // that looks at the present; for one that reads a record of what happened (Observation.Happened), + // how many times it happened, and LastObserved when it last did (novox/hq issue 402). Observations int `json:"observations"` // Count is how many times it has been raised, a reopening within ReopenWithin counted. Count int `json:"count"` @@ -208,6 +210,15 @@ type Observation struct { Said string Source string Resolver string + // Happened is set by a source that reads a record of what happened rather than looking at the + // present — a bus advisory, remembered for an hour and read again on every look — to when it last + // happened; Times is how many times the record counts it. The condition then counts what happened, + // not the looks (novox/hq issue 402): one refusal looked at every half minute read as "observed 15 + // time(s)", with a line of evidence every 30 seconds, and was taken for a refusal going on. A look + // that brings nothing newer than the condition's last observation adds no observation and no + // evidence. Zero for a source that looks at the present, whose every look is an observation. + Happened time.Time + Times int // Confirm says a single look can be wrong about this finding — a question over the network that // went unanswered, a time measured once on a loaded machine. The keeper does not read it: the // source that looks again does, and raises it only when the next look sees it too, or while it is diff --git a/internal/conditions/store.go b/internal/conditions/store.go index caca3c02..c36c1a4f 100644 --- a/internal/conditions/store.go +++ b/internal/conditions/store.go @@ -191,11 +191,16 @@ func (k *Keeper) Observe(ctx context.Context, o Observation) (Condition, error) if err != nil { return Condition{}, fmt.Errorf("reading the condition %s: %w", key, err) } + // What was observed and when: the look, or what the record says happened (novox/hq issue 402). + at, observations := now, 1 + if !o.Happened.IsZero() { + at, observations = o.Happened.UTC(), max(1, o.Times) + } if !found { c := Condition{Key: key, Kind: o.Kind, Subject: Subject{Scope: o.Scope, ID: o.ID, Machine: o.Machine, Also: o.Also}, Severity: o.Severity, Summary: o.Summary, Headline: o.Headline, Explanation: o.Explanation, - Resolved: o.Resolved, Needs: o.Needs, Actions: o.Actions, Evidence: []Evidence{{At: now, Said: said}}, - Source: o.Source, Raised: now, LastObserved: now, Observations: 1, Count: 1, + Resolved: o.Resolved, Needs: o.Needs, Actions: o.Actions, Evidence: []Evidence{{At: at, Said: said}}, + Source: o.Source, Raised: now, LastObserved: at, Observations: observations, Count: 1, Resolver: orSelf(o.Resolver)} change := ChangeRaised k.mu.Lock() @@ -244,7 +249,10 @@ func (k *Keeper) Observe(ctx context.Context, o Observation) (Condition, error) } // The kind as the source says it now: a source that gave the same key a kind of its own since // (a probe's finding split out for a healer) is read by that kind from its next observation. - c.Kind, c.Summary, c.Source, c.LastObserved = o.Kind, o.Summary, o.Source, now + // A record read again with nothing newer in it is not observed again: its words are refreshed, + // its count, evidence and last observation stay (novox/hq issue 402). + fresh := o.Happened.IsZero() || at.After(c.LastObserved) + c.Kind, c.Summary, c.Source = o.Kind, o.Summary, o.Source wasNeeds, wasActions := c.Needs, c.Actions c.Headline, c.Explanation, c.Resolved, c.Needs, c.Actions = o.Headline, o.Explanation, o.Resolved, o.Needs, o.Actions escalatedWords(&c) @@ -257,10 +265,15 @@ func (k *Keeper) Observe(ctx context.Context, o Observation) (Condition, error) if len(o.Also) > 0 { c.Subject.Also = o.Also } - c.Observations++ - c.Evidence = append([]Evidence{{At: now, Said: said}}, c.Evidence...) - if len(c.Evidence) > KeptEvidence { - c.Evidence = c.Evidence[:KeptEvidence] + if fresh { + // A record counts what happened since it began; the condition never counts down, so a + // record begun again (a controller restarted) still adds the one it shows. + c.Observations = max(c.Observations+1, o.Times) + c.LastObserved = at + c.Evidence = append([]Evidence{{At: at, Said: said}}, c.Evidence...) + if len(c.Evidence) > KeptEvidence { + c.Evidence = c.Evidence[:KeptEvidence] + } } if err := k.stamp(&c); err != nil { return Condition{}, err