From fb8d2386b971d2bac3f5a2634abf20ef7a2028dc Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 31 Oct 2026 21:59:46 +0100 Subject: [PATCH 1/2] Watchman: a module is unhealthy when its have still says failed a minute after it first did (issue 1952) A have that turned failed once and stayed unchanged was written once, so the old count of two writes never fired and the finding was never written (fail2ban on novox). Confirm by time, with a signal, also at a restart. Quick: raise the count to one write (loses the confirmation). Thorough, chosen: confirm by a time bound, as ADR 0564 s4's signals are keys that expire, so no write count is needed. Claude-Session: https://claude.ai/code/session_01NcbgfJ9Gum47zkFKWRaovL --- .../internal/watch/findings_test.go | 19 +++++++++----- .../internal/watch/signals.go | 25 +++++++++++++------ 2 files changed, 31 insertions(+), 13 deletions(-) diff --git a/modules/mesh-delivery-watchman/internal/watch/findings_test.go b/modules/mesh-delivery-watchman/internal/watch/findings_test.go index 03f8cac..3e8c5f0 100644 --- a/modules/mesh-delivery-watchman/internal/watch/findings_test.go +++ b/modules/mesh-delivery-watchman/internal/watch/findings_test.go @@ -143,18 +143,25 @@ func TestTheWatchmansFindings(t *testing.T) { w.Provisioned(ProvReport{Node: "g14", Module: "web", Status: ProvFailed, Reason: "x", At: t0.Add(-10 * time.Minute)}) w.Provisioned(ProvReport{Node: "ace", Module: "web", Status: "applied", At: t0}) }, map[string]string{}}, - {"WM3: unhealthy only at the second write in a row, urgent after four hours", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { + {"WM3: unhealthy once a failed have is confirmed after a minute (written once and steady); recovered within it none; urgent after four hours", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { w.Have("ace.web", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "the unit failed"), Put) if len(o.findings) != 0 { - t.Fatalf("one write raised %v", o.findings) + t.Fatalf("raised before its bound: %v", o.findings) } - w.Have("ace.web", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "the unit failed"), Put) - if o.findings["module.web.ace.unhealthy"].Severity != Warning { + w.Have("ace.quick", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "blip"), Put) + w.Have("ace.quick", haveOf(t, delivery.PhaseRunning, delivery.HealthOK, ""), Put) // recovered within the bound + expire(w, c, signalKey("unhealthy-confirm", "quick.ace"), UnhealthyConfirmAfter) + expire(w, c, signalKey("unhealthy-confirm", "web.ace"), UnhealthyConfirmAfter) // the one write, never repeated + if o.findings["module.web.ace.unhealthy"].Severity != Warning || len(o.findings) != 1 { t.Fatalf("findings = %v", o.findings) } expire(w, c, signalKey("unhealthy", "web.ace"), UnhealthyUrgentAfter) w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthWaits, "a part waits for the secret token"), Put) // needs-operator is not observed here }, map[string]string{"module.web.ace.unhealthy": Urgent}}, + {"WM3: a restart replays a have already failed: it is confirmed after a minute like a new one", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { + w.Have("novox.fail2ban", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "down since 19:40"), Put) + expire(w, c, signalKey("unhealthy-confirm", "fail2ban.novox"), UnhealthyConfirmAfter) + }, map[string]string{"module.fail2ban.novox.unhealthy": Warning}}, {"1954/D2: a provision in waits is its consumer's needs-operator; provided, it ends", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { enc := func(state, why string) []byte { b, err := provisions.Encode(provisions.Provision{Provision: "oidc", Consumer: provisions.End{Module: "photos", Node: "ace"}, @@ -267,7 +274,7 @@ func TestTheWatchmansFindings(t *testing.T) { }, map[string]string{}}, {"WM3: a have removed ends its findings", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) - w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) + expire(w, c, signalKey("unhealthy-confirm", "mail.ace"), UnhealthyConfirmAfter) w.Have("ace.mail", haveOf(t, delivery.PhaseRemoved, delivery.HealthUnknown, ""), Put) }, map[string]string{}}, {"WM2 S1: a control node silent is urgent after half an hour", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { @@ -314,7 +321,7 @@ func TestTheWatchmansFindings(t *testing.T) { }, map[string]string{}}, {"WM4: resync after a cleared bucket writes the same findings", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) - w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) + expire(w, c, signalKey("unhealthy-confirm", "mail.ace"), UnhealthyConfirmAfter) o.findings = map[string]Finding{} if n := w.Rewrite(); n != 1 { t.Fatalf("rewrote %d", n) diff --git a/modules/mesh-delivery-watchman/internal/watch/signals.go b/modules/mesh-delivery-watchman/internal/watch/signals.go index 214ee3f..3f3ace0 100644 --- a/modules/mesh-delivery-watchman/internal/watch/signals.go +++ b/modules/mesh-delivery-watchman/internal/watch/signals.go @@ -27,7 +27,7 @@ import ( // - S11, a machine's tool runner heartbeat on `mesh.control..tools-alive`: a pulse of three intervals; // - S21, a module's have failed: a pulse of one apply interval from the first failure, whose expiry while it still fails // is the finding `apply-failing`; -// - a module's have unhealthy in two writes in a row, `unhealthy`, urgent after four hours; and a have that waits for +// - a module's have still failed a minute after it first said so, `unhealthy`, urgent after four hours; and a have that waits for // the operator, `needs-operator` (ADR 0240 §12, §17). // The bounds of the rows. @@ -43,6 +43,8 @@ const ( HeartbeatEvery = 60 * time.Second // ApplyEvery is one apply interval (S21): a failure still there after it is not one the next apply clears. ApplyEvery = 5 * time.Minute + // UnhealthyConfirmAfter is how long a have must keep saying failed before the module is said unhealthy. + UnhealthyConfirmAfter = time.Minute // UnhealthyUrgentAfter is how long a module stays unhealthy before it is urgent. UnhealthyUrgentAfter = 4 * time.Hour // SilentBound is the bound S1 says, three of the intervals a machine has always used, and ControlNodeUrgentAfter @@ -471,6 +473,7 @@ func (w *Watchman) haveFindings(key string, node, module string, h *delivery.Hav delete(w.haveState, key) delete(w.unhealthy, key) delete(w.failedSince, key) + w.unsignal("unhealthy-confirm", module+"."+node) w.unsignal("unhealthy", module+"."+node) w.unfind(unhealthyKey) w.applyCheck(node) @@ -489,21 +492,29 @@ func (w *Watchman) haveFindings(key string, node, module string, h *delivery.Hav } w.applyCheck(node) - // unhealthy: two writes in a row that say it failed. + // unhealthy: a have that says failed and still says it after UnhealthyConfirmAfter (ADR 0564 §4's confirmation, by time: + // a have written once and then unchanged never gets a second write). The confirm signal's expiry writes the warning; a + // signal already standing (kept across a restart) is not renewed, so a steady have does not push its own expiry out. if h.Health == delivery.HealthFailed { - w.unhealthy[key]++ - if w.unhealthy[key] == 2 { + if w.unhealthy[key] == 0 { + w.unhealthy[key] = 1 f := Finding{Scope: ScopeModule, ID: module + "." + node, Token: "unhealthy", Kind: KindUnhealthy, Machine: node, Severity: Warning, Source: "health", Since: now, Summary: fmt.Sprintf("%s on %s is not healthy: %s", module, node, orWords(h.Detail, "its check failed")), Said: firstLine(orWords(h.Detail, "failed")), Headline: fmt.Sprintf("%s not working on %s", module, node)} - w.find(f) - f.Severity = Urgent - w.signal("unhealthy", module+"."+node, UnhealthyUrgentAfter, signalDue{Do: dueFind, While: key, Finding: f}) + id := module + "." + node + if _, ok := w.signals[signalKey("unhealthy-confirm", id)]; !ok { + w.signal("unhealthy-confirm", id, UnhealthyConfirmAfter, signalDue{Do: dueFind, While: key, Finding: f}) + } + if _, ok := w.signals[signalKey("unhealthy", id)]; !ok { + f.Severity = Urgent + w.signal("unhealthy", id, UnhealthyUrgentAfter, signalDue{Do: dueFind, While: key, Finding: f}) + } } } else { delete(w.unhealthy, key) + w.unsignal("unhealthy-confirm", module+"."+node) w.unsignal("unhealthy", module+"."+node) w.unfind(unhealthyKey) } From 8a658a4290c965cc09ecb2e5322020da27f62234 Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 31 Oct 2026 22:01:59 +0100 Subject: [PATCH 2/2] Watchman: an unhealthy finding read back at the start is kept as it was (issue 1952) At a restart a standing finding is observed again by the replayed failed have: kept, not confirmed again, and its urgent signal runs on from the finding's Since; an urgent one stays urgent with no signal restarted. Quick: skip the confirm when a finding stands. Thorough, chosen: the same, plus urgency read from the finding itself. Claude-Session: https://claude.ai/code/session_01NcbgfJ9Gum47zkFKWRaovL --- .../internal/watch/findings_test.go | 31 +++++++++++++++++++ .../internal/watch/signals.go | 17 ++++++++-- 2 files changed, 45 insertions(+), 3 deletions(-) diff --git a/modules/mesh-delivery-watchman/internal/watch/findings_test.go b/modules/mesh-delivery-watchman/internal/watch/findings_test.go index 3e8c5f0..4466789 100644 --- a/modules/mesh-delivery-watchman/internal/watch/findings_test.go +++ b/modules/mesh-delivery-watchman/internal/watch/findings_test.go @@ -158,6 +158,29 @@ func TestTheWatchmansFindings(t *testing.T) { expire(w, c, signalKey("unhealthy", "web.ace"), UnhealthyUrgentAfter) w.Have("ace.mail", haveOf(t, delivery.PhaseRunning, delivery.HealthWaits, "a part waits for the secret token"), Put) // needs-operator is not observed here }, map[string]string{"module.web.ace.unhealthy": Urgent}}, + {"WM3: a warning unhealthy finding read back at the start is kept as it was, urgent when its four hours from Since are out", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { + seedUnhealthy(t, w, o, Warning, t0.Add(-time.Hour)) + w.Have("ace.web", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) + w.Reconcile() + if o.findings["module.web.ace.unhealthy"].Severity != Warning { + t.Fatalf("cleared: findings %v", o.findings) + } + if ttl := o.ttls[signalKey("unhealthy", "web.ace")]; ttl != UnhealthyUrgentAfter-time.Hour { + t.Fatalf("urgent signal restarted from zero: %v", ttl) + } + if _, ok := w.signals[signalKey("unhealthy-confirm", "web.ace")]; ok { + t.Fatal("a standing finding is confirmed again") + } + expire(w, c, signalKey("unhealthy", "web.ace"), UnhealthyUrgentAfter-time.Hour) + }, map[string]string{"module.web.ace.unhealthy": Urgent}}, + {"WM3: an urgent unhealthy finding read back at the start stays urgent, with no signal restarted", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { + seedUnhealthy(t, w, o, Urgent, t0.Add(-5*time.Hour)) + w.Have("ace.web", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "x"), Put) + w.Reconcile() + if o.findings["module.web.ace.unhealthy"].Severity != Urgent || len(w.signals) != 0 { + t.Fatalf("findings %v signals %v", o.findings, w.signals) + } + }, map[string]string{"module.web.ace.unhealthy": Urgent}}, {"WM3: a restart replays a have already failed: it is confirmed after a minute like a new one", func(t *testing.T, w *Watchman, o *fakeOut, c *clock) { w.Have("novox.fail2ban", haveOf(t, delivery.PhaseRunning, delivery.HealthFailed, "down since 19:40"), Put) expire(w, c, signalKey("unhealthy-confirm", "fail2ban.novox"), UnhealthyConfirmAfter) @@ -370,3 +393,11 @@ func TestTheWatchmansFindings(t *testing.T) { }) } } + +func seedUnhealthy(t *testing.T, w *Watchman, o *fakeOut, sev string, since time.Time) { + t.Helper() + f := Finding{Scope: ScopeModule, ID: "web.ace", Token: "unhealthy", Kind: KindUnhealthy, Machine: "ace", Severity: sev, Source: "health", Since: since, Summary: "web on ace is not healthy: x"} + v, _ := EncodeFinding(f) + o.findings[f.Key()], _ = DecodeFinding(v) + w.SeedFinding(f.Key(), v) +} diff --git a/modules/mesh-delivery-watchman/internal/watch/signals.go b/modules/mesh-delivery-watchman/internal/watch/signals.go index 3f3ace0..e28ec1e 100644 --- a/modules/mesh-delivery-watchman/internal/watch/signals.go +++ b/modules/mesh-delivery-watchman/internal/watch/signals.go @@ -504,12 +504,23 @@ func (w *Watchman) haveFindings(key string, node, module string, h *delivery.Hav Said: firstLine(orWords(h.Detail, "failed")), Headline: fmt.Sprintf("%s not working on %s", module, node)} id := module + "." + node - if _, ok := w.signals[signalKey("unhealthy-confirm", id)]; !ok { + urgentIn := UnhealthyUrgentAfter + if w.seededFindings[unhealthyKey] { + // Read back at the start: it stands, so it is observed again, kept as it was (not cleared and raised again), and + // its four hours run on from its own Since, not from zero; one that already went urgent needs no signal. + delete(w.seededFindings, unhealthyKey) + old, err := DecodeFinding(w.findings[unhealthyKey]) + if err == nil && old.Severity == Urgent { + urgentIn = 0 + } else if err == nil && !old.Since.IsZero() { + urgentIn = max(time.Second, UnhealthyUrgentAfter-now.Sub(old.Since)) + } + } else if _, ok := w.signals[signalKey("unhealthy-confirm", id)]; !ok { w.signal("unhealthy-confirm", id, UnhealthyConfirmAfter, signalDue{Do: dueFind, While: key, Finding: f}) } - if _, ok := w.signals[signalKey("unhealthy", id)]; !ok { + if _, ok := w.signals[signalKey("unhealthy", id)]; !ok && urgentIn > 0 { f.Severity = Urgent - w.signal("unhealthy", id, UnhealthyUrgentAfter, signalDue{Do: dueFind, While: key, Finding: f}) + w.signal("unhealthy", id, urgentIn, signalDue{Do: dueFind, While: key, Finding: f}) } } } else {