Z16 zfs-health: a refused or failed command in the applied state is unhealthy naming its key, and the module's own warnings

Builds: design 42 zfs-owns-zfs §29, §15, A-35

modules/zfs/cmd/zfs-tools/health.go

@@ -37,6 +37,8 @@ type Look struct {
 	ScheduleErr error
 	// Served is the last slot the scheduled run served, per pool.
 	Served map[string]int64
+	// Module is what the module's own config, states and ledger say (§29); nil judges the pools alone.
+	Module *ModuleLook
 }
 
 // errorFinding judges one line of status's error counts against the last look: a count that rose is a
@@ -174,6 +176,10 @@ func (mem *ErrorMemory) Judge(l Look) Health {
 	if l.Schedule != nil && statusOf(l.Status, l.Schedule.Pool) == nil {
 		warn = append(warn, fmt.Sprintf("The scrub schedule names pool %s, which is not imported here.", l.Schedule.Pool))
 	}
+	if l.Module != nil {
+		f, w := l.moduleFindings()
+		found, warn = append(found, f...), append(warn, w...)
+	}
 	mem.save()
 	if len(found) > 0 {
 		return Health{Healthy: false, Why: strings.Join(found, " "), Found: found, Warnings: warn}
@@ -205,7 +211,7 @@ func (m *Machine) Health(ctx context.Context) Health {
 	}
 	sched, serr := m.ScheduleNow(ctx)
 	return m.Errors.Judge(Look{Pools: pools, Status: status, Now: m.Now(), Schedule: sched, ScheduleErr: serr,
-		Served: m.readServed(ServedFile)})
+		Served: m.readServed(ServedFile), Module: m.moduleLook()})
 }
 
 func sentence(s string) string {

modules/zfs/cmd/zfs-tools/health_module.go

@@ -0,0 +1,152 @@
+package main
+
+import (
+	"encoding/json"
+	"fmt"
+	"strings"
+	"time"
+)
+
+// What the module's own work adds to its health (design 42 zfs-owns-zfs §29, §15).
+//
+// Unhealthy: a `refused` (the hostid's among them) or a failed command in the state `applied`, naming the key and
+// why. Warnings: a wait, naming on what and since when; a parameter awaiting a load of the kernel module; a
+// `.pacnew` beside a package file; the last scheduled ZFS snapshot of a kind older than its cadence; `autoreplace` on
+// or a spare in the pool while `zed` is not `on`; the pool above 80 % with `snapshots` set; scheduled ZFS snapshots
+// kept after `snapshots` went to `none` (or a kind's keep count to 0); `paused` set.
+
+// ModuleLook is what one health check read of the module's own config, states and ledger.
+type ModuleLook struct {
+	Config  *Config
+	Applied map[string]AppliedEntry
+	Paused  bool
+	// Ledger is the scheduled ZFS snapshots; LedgerKnown says whether it could be read.
+	Ledger      []LedgerEntry
+	LedgerKnown bool
+	// Pacnew are the package files a `.pacnew` lies beside.
+	Pacnew []string
+}
+
+// snapshotLate is how old the last scheduled ZFS snapshot of a kind may be before it is a warning: its cadence and
+// the margin for a run that waited for the lock or a full pool.
+var snapshotLate = map[string]time.Duration{"hourly": 2 * time.Hour, "daily": 36 * time.Hour, "weekly": 9 * 24 * time.Hour,
+	"monthly": 38 * 24 * time.Hour}
+
+// moduleLook reads what the module itself keeps. It answers nil when the config file is not readable or not valid:
+// the module is then judged on its pools alone, and the refusal is already in the state `applied`.
+func (m *Machine) moduleLook() *ModuleLook {
+	text, err := m.ReadFile(ConfigFile)
+	if err != nil {
+		return nil
+	}
+	c, refused := ParseConfig(text, m.memMiB())
+	if len(refused) > 0 {
+		c = nil
+	}
+	l := &ModuleLook{Config: c, Applied: map[string]AppliedEntry{}}
+	if m.States != nil {
+		if keys, err := m.States.Keys(StateApplied); err == nil {
+			for _, k := range keys {
+				if raw, ok, _ := m.States.Get(StateApplied, k); ok {
+					var e AppliedEntry
+					if json.Unmarshal(raw, &e) == nil {
+						l.Applied[k] = e
+					}
+				}
+			}
+		}
+	}
+	l.Paused = m.Paused()
+	if m.Ledger != nil {
+		if es, err := m.Ledger.Entries(); err == nil {
+			l.Ledger, l.LedgerKnown = es, true
+		}
+	}
+	for _, p := range []string{"/etc/default/zfs", "/etc/zfs/zed.d/zed.rc"} {
+		if m.exists(p + ".pacnew") {
+			l.Pacnew = append(l.Pacnew, p)
+		}
+	}
+	return l
+}
+
+// moduleFindings judges the module's own work.
+func (l Look) moduleFindings() (found, warn []string) {
+	k := l.Module
+	for _, key := range sortedKeys(k.Applied) {
+		e := k.Applied[key]
+		switch e.Outcome {
+		case OutcomeRefused:
+			found = append(found, sentence(fmt.Sprintf("%s is refused: %s", key, e.Why)))
+		case OutcomeFailed:
+			found = append(found, sentence(fmt.Sprintf("a command for %s failed: %s", key, e.Why)))
+		case OutcomeWaiting:
+			since := "a time not said"
+			if !e.Since.IsZero() {
+				since = e.Since.Local().Format("2006-01-02 15:04")
+			}
+			warn = append(warn, sentence(fmt.Sprintf("%s waits on %s since %s", key, e.WaitsOn, since)))
+		case OutcomeAwaitingLoad:
+			warn = append(warn, sentence(fmt.Sprintf("%s takes effect at the next load of the kernel module", key)))
+		}
+	}
+	for _, p := range k.Pacnew {
+		warn = append(warn, sentence(p+".pacnew lies beside it: the package shipped a newer file the module does not take"))
+	}
+	if k.Paused {
+		warn = append(warn, "The scheduled ZFS snapshots are paused: none is taken or removed.")
+	}
+	c := k.Config
+	if c == nil {
+		return found, warn
+	}
+	if c.Zed != "on" {
+		spare := false
+		for _, p := range l.Status {
+			if p.Name == c.Pool {
+				if s := sectionOf(&p, "spare"); s != nil && len(s.Children) > 0 {
+					spare = true
+				}
+			}
+		}
+		if c.PoolProperties["autoreplace"] == "on" || spare {
+			warn = append(warn, "Pool "+c.Pool+" has autoreplace on or a spare, and zed is not on: nothing replaces a failed device by itself.")
+		}
+	}
+	if c.Snapshots != nil && !c.Snapshots.None {
+		for _, p := range l.Pools {
+			if p.Name == c.Pool && p.Capacity > FullPercent {
+				warn = append(warn, fmt.Sprintf("Pool %s is %d %% full, past %d %%: no scheduled ZFS snapshot is taken.", p.Name, p.Capacity, FullPercent))
+			}
+		}
+	}
+	if !k.LedgerKnown {
+		return found, warn
+	}
+	if c.Snapshots != nil && !c.Snapshots.None {
+		for _, kind := range keepsOf(c.Snapshots) {
+			var last time.Time
+			for _, e := range k.Ledger {
+				if at, err := time.Parse(time.RFC3339, e.At); err == nil && e.Kind == kind && at.After(last) {
+					last = at
+				}
+			}
+			if !last.IsZero() && l.Now.Sub(last) > snapshotLate[kind] {
+				warn = append(warn, fmt.Sprintf("The last scheduled %s ZFS snapshot is from %s, older than its cadence allows.", kind, last.Local().Format("2006-01-02 15:04")))
+			}
+		}
+	}
+	kept := map[string][]string{}
+	for _, e := range k.Ledger {
+		if c.Snapshots == nil || c.Snapshots.None || c.Snapshots.Of(e.Kind) == 0 {
+			kept[e.Kind] = append(kept[e.Kind], e.Dataset+"@"+e.Name)
+		}
+	}
+	for _, kind := range keepKinds {
+		if len(kept[kind]) > 0 {
+			warn = append(warn, fmt.Sprintf("%d scheduled %s ZFS snapshots are kept though snapshots does not ask for them (none or a keep count of 0 removes nothing): %s.",
+				len(kept[kind]), kind, strings.Join(kept[kind], ", ")))
+		}
+	}
+	return found, warn
+}

modules/zfs/cmd/zfs-tools/health_test.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"strings"
 	"testing"
+	"time"
 )
 
 func TestOnlinePoolsWithoutErrorsAreHealthyAndAnOldScrubIsOnlyAWarning(t *testing.T) {
@@ -108,3 +109,73 @@ func TestTheFollowerArgvAndAResilverStartAndFinishAreJournaled(t *testing.T) {
 		t.Errorf("the resilver's start: %q", out.String())
 	}
 }
+
+// §29, §15: a refused (the hostid's among them) or failed command in the state `applied` is unhealthy naming the key
+// and why, and healthy again once it is gone; each warning of §29 is a warning and leaves the module healthy.
+func TestTheModulesOwnWorkAddsToItsHealthAsSection29Says(t *testing.T) {
+	st, _ := ParseStatus(fixture(t, "zpool-status-scrubbing.txt"))
+	now := newFake(t).now
+	snap := func(json string) *Config {
+		c, ref := ParseConfig([]byte(json), 16000)
+		if len(ref) != 0 {
+			t.Fatal(ref)
+		}
+		return c
+	}
+	entry := func(kind string, h int) LedgerEntry {
+		return LedgerEntry{"tank", "mesh-" + kind + "-x", kind, now.Add(-time.Duration(h) * time.Hour).UTC().Format(time.RFC3339)}
+	}
+	cases := []struct {
+		name      string
+		look      ModuleLook
+		capacity  int
+		unhealthy string
+		warning   string
+	}{
+		{name: "hostid refused", look: ModuleLook{Applied: map[string]AppliedEntry{"hostid": {Outcome: OutcomeRefused, Why: "the pool's import would need -f"}}},
+			unhealthy: "Hostid is refused: the pool's import would need -f"},
+		{name: "a failed command", look: ModuleLook{Applied: map[string]AppliedEntry{"cache-devices": {Outcome: OutcomeFailed, Why: "zpool add failed"}}},
+			unhealthy: "a command for cache-devices failed: zpool add failed"},
+		{name: "a wait", look: ModuleLook{Applied: map[string]AppliedEntry{"cache-devices": {Outcome: OutcomeWaiting, WaitsOn: "a scrub of tank", Since: now}}},
+			warning: "waits on a scrub of tank since"},
+		{name: "awaiting a load", look: ModuleLook{Applied: map[string]AppliedEntry{"module-options.zfs_txg_timeout": {Outcome: OutcomeAwaitingLoad}}},
+			warning: "takes effect at the next load of the kernel module"},
+		{name: "a pacnew", look: ModuleLook{Pacnew: []string{"/etc/default/zfs"}}, warning: "/etc/default/zfs.pacnew"},
+		{name: "paused", look: ModuleLook{Paused: true}, warning: "are paused"},
+		{name: "last snapshot older than its cadence", look: ModuleLook{Config: snap(`{"pool":"tank","snapshots":{"hourly":2}}`), LedgerKnown: true,
+			Ledger: []LedgerEntry{entry("hourly", 5)}}, warning: "last scheduled hourly ZFS snapshot"},
+		{name: "autoreplace without zed", look: ModuleLook{Config: snap(`{"pool":"tank","pool-properties":{"autoreplace":"on"}}`)}, warning: "autoreplace on or a spare"},
+		{name: "pool above 80 % with snapshots", look: ModuleLook{Config: snap(`{"pool":"tank","snapshots":{"daily":2}}`)}, capacity: 85, warning: "no scheduled ZFS snapshot is taken"},
+		{name: "kept after none", look: ModuleLook{Config: snap(`{"pool":"tank","snapshots":{"none":true}}`), LedgerKnown: true, Ledger: []LedgerEntry{entry("daily", 1)}},
+			warning: "kept though snapshots does not ask for them"},
+		{name: "kept at a keep count of 0", look: ModuleLook{Config: snap(`{"pool":"tank","snapshots":{"hourly":0,"daily":1}}`), LedgerKnown: true,
+			Ledger: []LedgerEntry{entry("hourly", 1), entry("daily", 1)}}, warning: "1 scheduled hourly ZFS snapshots are kept"},
+		{name: "nothing to say", look: ModuleLook{Config: snap(`{"pool":"tank","snapshots":{"daily":2}}`), LedgerKnown: true, Ledger: []LedgerEntry{entry("daily", 1)}}},
+	}
+	for _, c := range cases {
+		look := c.look
+		if look.Applied == nil {
+			look.Applied = map[string]AppliedEntry{}
+		}
+		cap := c.capacity
+		if cap == 0 {
+			cap = 50
+		}
+		h := NewErrorMemory().Judge(Look{Pools: []Pool{{Name: "tank", Capacity: cap, Health: "ONLINE"}}, Status: st, Now: now, Module: &look})
+		if c.unhealthy != "" {
+			if h.Healthy || !strings.Contains(strings.ToLower(h.Why), strings.ToLower(c.unhealthy)) {
+				t.Errorf("%s: %+v", c.name, h)
+			}
+			continue
+		}
+		all := strings.Join(h.Warnings, " ")
+		if !h.Healthy || (c.warning == "" && len(h.Warnings) != 0) || (c.warning != "" && !strings.Contains(all, c.warning)) {
+			t.Errorf("%s: %+v", c.name, h)
+		}
+	}
+	// Once the refusal is gone the module is healthy again.
+	if h := NewErrorMemory().Judge(Look{Pools: []Pool{{Name: "tank", Capacity: 50, Health: "ONLINE"}}, Status: st, Now: now,
+		Module: &ModuleLook{Applied: map[string]AppliedEntry{}}}); !h.Healthy {
+		t.Errorf("after the refusal: %+v", h)
+	}
+}