Merge pull request 'The watchman confirms a module unhealthy by time, and keeps a standing finding across its restart (issue 1952)' (#127) from fix/watchman-confirm into main

modules/mesh-delivery-watchman/internal/watch/findings_test.go

@@ -143,18 +143,48 @@ 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 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)
+		}, 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 +297,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 +344,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)
@@ -363,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)
+}

modules/mesh-delivery-watchman/internal/watch/signals.go

@@ -27,7 +27,7 @@ import (
 //   - S11, a machine's tool runner heartbeat on `mesh.control.<node>.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,40 @@ 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
+			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 && urgentIn > 0 {
+				f.Severity = Urgent
+				w.signal("unhealthy", id, urgentIn, 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)
 	}