diff --git a/modules/mesh-delivery-watchman/internal/watch/findings_test.go b/modules/mesh-delivery-watchman/internal/watch/findings_test.go index 03f8cac..4466789 100644 --- a/modules/mesh-delivery-watchman/internal/watch/findings_test.go +++ b/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) +} diff --git a/modules/mesh-delivery-watchman/internal/watch/signals.go b/modules/mesh-delivery-watchman/internal/watch/signals.go index 214ee3f..e28ec1e 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,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) }