jochen
bd0182785c
The second review of #147 found three blockers before the home server. 1. ${setting:} was not filled in a unit's name, so the distribution timers would have reached the machine as "zfs-scrub-weekly@${setting:scrub-pool}.timer". mesh-controller #171 fills it and refuses any value that is not a unit-name part. The module's own schedule needs no setting in a name now: the node-engine's timer for the scheduled process zfs-mesh-scrub fires `zfs-tools scrub-run` every quarter of an hour, and the run reads the pool, cadence, day and time from the configuration file. 2. The run does what upstream's zfs-scrub@.service does: if a scrub is running it waits for it with zpool wait -t scrub, otherwise it starts one and waits. It never pauses or stops a scrub, and the unit has no ExecStop. A resilver defers the scrub. The served slot is kept in /var/lib/zfs-tools. 3. Unassigning left the pool with no schedule. mesh-host #66 (hq ADR 0269, proposed) gives the distribution timer back running and enabled. The README says not to unassign before it is merged. Also: the run comes before the distribution timers in the declaration; the day and time are checked against fixed sets and reach no unit file (an invalid value runs nothing); a due scrub not started an hour after its time is a warning; the error counts outlive a restart in a small state file.
340 lines
13 KiB
Go
340 lines
13 KiB
Go
package main
|
|
|
|
// The safety review of the first version (mesh-catalog 90516fc) and the operator's scrub requirement:
|
|
// each test here failed against that version, or did not compile against it.
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"errors"
|
|
"fmt"
|
|
"io"
|
|
"os"
|
|
"path/filepath"
|
|
"strconv"
|
|
"strings"
|
|
"syscall"
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
// A command that does not answer in time is ended with every process it started: the runner puts it in a
|
|
// process group of its own and signals the group, so a child holding the output open (as zfs under sudo
|
|
// does) cannot keep the call waiting.
|
|
func TestATimedOutCommandIsEndedWithItsChildren(t *testing.T) {
|
|
old := KillGrace
|
|
KillGrace = 300 * time.Millisecond
|
|
defer func() { KillGrace = old }()
|
|
pidFile := filepath.Join(t.TempDir(), "child")
|
|
ctx, cancel := context.WithTimeout(context.Background(), 300*time.Millisecond)
|
|
defer cancel()
|
|
start := time.Now()
|
|
r := ExecRunner(ctx, "sh", "-c", "sleep 30 & echo $! > "+pidFile+"; wait")
|
|
if took := time.Since(start); took > 5*time.Second {
|
|
t.Fatalf("the call waited %s for a child holding its output", took)
|
|
}
|
|
if !r.TimedOut {
|
|
t.Errorf("not said as timed out: %+v", r)
|
|
}
|
|
b, err := os.ReadFile(pidFile)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
pid, _ := strconv.Atoi(strings.TrimSpace(string(b)))
|
|
time.Sleep(100 * time.Millisecond)
|
|
if err := syscall.Kill(pid, 0); err == nil {
|
|
syscall.Kill(pid, syscall.SIGKILL)
|
|
t.Errorf("the child %d outlived the timeout", pid)
|
|
}
|
|
}
|
|
|
|
func TestTheSnapshotHasNoRecursiveAndSaysWhatItWillHold(t *testing.T) {
|
|
f := withZFS(t)
|
|
snapshotting(f, takeLine, "tank/media@before-move\t1791400000\t0\t26938034880512")
|
|
m := f.machine()
|
|
var take func(map[string]any) (any, error)
|
|
for _, tl := range Tools(m) {
|
|
if tl.Name == "zfs_snapshot" {
|
|
take = tl.Run
|
|
if _, has := tl.Input["recursive"]; has {
|
|
t.Errorf("zfs_snapshot still offers recursive")
|
|
}
|
|
}
|
|
}
|
|
if _, err := take(map[string]any{"dataset": "tank", "name": "x", "why": "y", "recursive": true}); err == nil ||
|
|
!strings.Contains(err.Error(), "recursive") {
|
|
t.Errorf("a recursive argument is refused, not ignored: %v", err)
|
|
}
|
|
if n := len(ran(f, "sudo")); n != 0 {
|
|
t.Errorf("the refusal ran %v", f.calls)
|
|
}
|
|
got, err := take(map[string]any{"dataset": "tank/media", "name": "before-move", "why": "before moving the library"})
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
a := got.(SnapshotAnswer)
|
|
if a.Available != 11203942195200 || a.PoolCapacity != 60 || a.Pool != "tank" {
|
|
t.Errorf("free space and capacity: %+v", a)
|
|
}
|
|
for _, want := range []string{"10.2 TiB free", "pool tank 60 % full",
|
|
"holds every block of tank/media deleted or overwritten from now on", "until it is destroyed by hand"} {
|
|
if !strings.Contains(a.Said, want) {
|
|
t.Errorf("said lacks %q: %s", want, a.Said)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestASnapshotThatTimedOutIsOutcomeUnknownUnlessTheListShowsIt(t *testing.T) {
|
|
f := withZFS(t)
|
|
f.answers[takeLine] = Ran{Code: -1, TimedOut: true, Err: "did not answer within its time"}
|
|
_, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why")
|
|
if err == nil || !strings.Contains(err.Error(), "outcome unknown; check zfs_snapshots") || strings.Contains(err.Error(), "NOT DONE") {
|
|
t.Errorf("timed out, not shown: %v", err)
|
|
}
|
|
f = withZFS(t)
|
|
snapshotting(f, takeLine, "tank/media@before-move\t1791400000\t0\t1")
|
|
f.answers[takeLine] = Ran{Code: -1, TimedOut: true}
|
|
a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why")
|
|
if err != nil || !a.Done {
|
|
t.Errorf("timed out and shown by the list: done (%v, %+v)", err, a)
|
|
}
|
|
}
|
|
|
|
// The follower starts at the start of the kernel's queue, writes each notable event once across its own
|
|
// restarts, says what ZFS dropped, and records where it got to.
|
|
func TestTheFollowerWritesTheQueueFromItsStartOnceAndWhatWasDropped(t *testing.T) {
|
|
cur := &Cursor{}
|
|
var out bytes.Buffer
|
|
input := "dropped 2 events\n" + fixture(t, "zpool-events.txt")
|
|
if err := Follow(strings.NewReader(input), &out, cur); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
lines := strings.Split(strings.TrimSpace(out.String()), "\n")
|
|
if len(lines) != 4 || !strings.Contains(lines[0], "ZFS dropped 2 events") || !strings.Contains(lines[1], "ereport.fs.zfs.io") ||
|
|
!strings.Contains(lines[3], "resilver_start") {
|
|
t.Fatalf("lines: %q", lines)
|
|
}
|
|
if cur.EID != 0x14 {
|
|
t.Errorf("the cursor is the last event read: %+v", cur)
|
|
}
|
|
// Restarted within the same boot: the queue is read again from its start, and nothing is written twice.
|
|
out.Reset()
|
|
if err := Follow(strings.NewReader(fixture(t, "zpool-events.txt")), &out, cur); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if out.Len() != 0 {
|
|
t.Errorf("written twice: %q", out.String())
|
|
}
|
|
// ZFS's module reloaded: its counter starts again, and an event after the cursor's time is new.
|
|
reloaded := strings.ReplaceAll(fixture(t, "zpool-events.txt"), "Oct 8 2026", "Oct 9 2026")
|
|
out.Reset()
|
|
Follow(strings.NewReader(reloaded), &out, cur)
|
|
if strings.Count(out.String(), "\n") != 3 {
|
|
t.Errorf("after a reload: %q", out.String())
|
|
}
|
|
}
|
|
|
|
func TestTheCursorIsKeptPerBoot(t *testing.T) {
|
|
dir := t.TempDir()
|
|
path := filepath.Join(dir, "cursor")
|
|
c := &Cursor{Boot: "a", EID: 7, Time: time.Date(2026, 10, 8, 21, 0, 0, 0, time.Local)}
|
|
if err := c.Save(path); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if got := LoadCursor(path, "a"); got.EID != 7 || !got.Time.Equal(c.Time) {
|
|
t.Errorf("same boot: %+v", got)
|
|
}
|
|
if got := LoadCursor(path, "b"); got.EID != 0 || got.Boot != "b" {
|
|
t.Errorf("another boot starts from the queue's start: %+v", got)
|
|
}
|
|
}
|
|
|
|
// fakeFollow is a zpool events -f whose output is given, and which records how it was ended.
|
|
type fakeFollow struct {
|
|
out io.Reader
|
|
killed bool
|
|
waited bool
|
|
order []string
|
|
}
|
|
|
|
func (p *fakeFollow) Stdout() io.Reader { return p.out }
|
|
func (p *fakeFollow) Kill() error {
|
|
p.killed = true
|
|
p.order = append(p.order, "kill")
|
|
return nil
|
|
}
|
|
func (p *fakeFollow) Wait() error {
|
|
p.waited = true
|
|
p.order = append(p.order, "wait")
|
|
return errors.New("signal: killed")
|
|
}
|
|
|
|
func TestAFollowThatFailsIsKilledBeforeItIsWaitedFor(t *testing.T) {
|
|
long := "Oct 8 2026 21:01:55.889900112 " + strings.Repeat("x", 2<<20) + "\n"
|
|
p := &fakeFollow{out: strings.NewReader(long)}
|
|
err := FollowOnce(p, io.Discard, &Cursor{})
|
|
if err == nil || strings.Join(p.order, ",") != "kill,wait" {
|
|
t.Errorf("err %v, order %v", err, p.order)
|
|
}
|
|
}
|
|
|
|
func TestTheFollowerGivesUpAfterRepeatedFailuresSoItsUnitShowsIt(t *testing.T) {
|
|
starts := 0
|
|
start := func(context.Context) (FollowProcess, error) {
|
|
starts++
|
|
return nil, fmt.Errorf("zpool: no such file")
|
|
}
|
|
var out bytes.Buffer
|
|
err := RunFollower(context.Background(), &out, start, &Cursor{}, "", func(time.Duration) {})
|
|
if err == nil || starts != MaxFollowFailures {
|
|
t.Errorf("err %v after %d starts", err, starts)
|
|
}
|
|
if !strings.Contains(out.String(), "zpool: no such file") {
|
|
t.Errorf("each failure is said: %q", out.String())
|
|
}
|
|
}
|
|
|
|
// Past error counts are a warning to clear by hand; a count that rises is a fault now.
|
|
func TestPastErrorsWarnAndNewErrorsAreUnhealthy(t *testing.T) {
|
|
f := newFake(t)
|
|
f.on(line("zpool", PoolsArgv()), "slow\t1000\t100\t900\t10\t1\tONLINE\t1.00\n")
|
|
f.on(line("zpool", StatusArgv()), fixtureSection(t, "zpool-status-rebuild.txt", "slow"))
|
|
m := f.machine()
|
|
h := m.Health(context.Background())
|
|
if !h.Healthy || !strings.Contains(strings.Join(h.Warnings, " "), "sda in pool slow has 2 past checksum errors; clear them by hand once understood") {
|
|
t.Fatalf("first look: %+v", h)
|
|
}
|
|
f.now = f.now.Add(time.Minute)
|
|
f.on(line("zpool", StatusArgv()), strings.Replace(fixtureSection(t, "zpool-status-rebuild.txt", "slow"), "0 0 2", "0 0 5", 1))
|
|
h = m.Health(context.Background())
|
|
if h.Healthy || !strings.Contains(h.Why, "sda in pool slow: checksum errors rose from 2 to 5") {
|
|
t.Fatalf("a rise: %+v", h)
|
|
}
|
|
f.now = f.now.Add(time.Minute)
|
|
if h := m.Health(context.Background()); h.Healthy {
|
|
t.Errorf("a rise stays unhealthy for %s, so two looks see it: %+v", ErrorsFresh, h)
|
|
}
|
|
f.now = f.now.Add(ErrorsFresh)
|
|
if h := m.Health(context.Background()); !h.Healthy || !strings.Contains(strings.Join(h.Warnings, " "), "5 past checksum errors") {
|
|
t.Errorf("after %s without a rise, a warning: %+v", ErrorsFresh, h)
|
|
}
|
|
}
|
|
|
|
func TestAResilverRunningWarnsAndOneFinishedWithErrorsIsUnhealthy(t *testing.T) {
|
|
f := newFake(t)
|
|
f.on(line("zpool", PoolsArgv()), "fast\t1000\t100\t900\t10\t1\tONLINE\t1.00\n")
|
|
f.on(line("zpool", StatusArgv()), fixtureSection(t, "zpool-status-rebuild.txt", "fast"))
|
|
h := f.machine().Health(context.Background())
|
|
if !h.Healthy || !strings.Contains(strings.Join(h.Warnings, " "), "A resilver of mirror-1 in pool fast is running: 16.84 % done, 02:40:11 to go") {
|
|
t.Errorf("running: %+v", h)
|
|
}
|
|
f.on(line("zpool", StatusArgv()), strings.Replace(fixtureSection(t, "zpool-status-rebuild.txt", "fast"),
|
|
"1.20T in 03:22:11 with 0 errors", "1.20T in 03:22:11 with 4 errors", 1))
|
|
if h := newMachineLike(f).Health(context.Background()); h.Healthy || !strings.Contains(h.Why, "The resilver of mirror-0 in pool fast finished with 4 errors") {
|
|
t.Errorf("finished with errors: %+v", h)
|
|
}
|
|
}
|
|
|
|
func newMachineLike(f *fake) *Machine { return f.machine() }
|
|
|
|
// fixtureSection is one pool's part of a status fixture.
|
|
func fixtureSection(t *testing.T, name, pool string) string {
|
|
t.Helper()
|
|
all := fixture(t, name)
|
|
start := strings.Index(all, " pool: "+pool+"\n")
|
|
if start < 0 {
|
|
t.Fatalf("no pool %s in %s", pool, name)
|
|
}
|
|
rest := all[start+1:]
|
|
if end := strings.Index(rest, "\n pool: "); end >= 0 {
|
|
return all[start : start+1+end+1]
|
|
}
|
|
return all[start:]
|
|
}
|
|
|
|
// The scan line's sizes are human even under -p (zfs_nicebytes in print_scan_scrub_resilver_status), and
|
|
// status prints a rebuild's resilver per vdev and an error scrub under `scrub:`.
|
|
func TestEveryScanLineOfTheSourceIsRead(t *testing.T) {
|
|
st, err := ParseStatus(fixture(t, "zpool-status-rebuild.txt"))
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
fast, slow, paused := st[0], st[1], st[2]
|
|
if len(fast.Scans) != 3 {
|
|
t.Fatalf("fast: an error scrub and two rebuilds: %+v", fast.Scans)
|
|
}
|
|
es := fast.Scans[0]
|
|
if es.Kind != "error scrub" || es.State != "finished" || es.Took != "0 days 00:01:02" || es.Ended == nil {
|
|
t.Errorf("error scrub: %+v", es)
|
|
}
|
|
done, running := fast.Scans[1], fast.Scans[2]
|
|
if done.Kind != "resilver" || done.Vdev != "mirror-0" || done.State != "finished" || done.Repaired != "1.20T" || deref(done.Errors) != 0 {
|
|
t.Errorf("finished rebuild: %+v", done)
|
|
}
|
|
if running.Vdev != "mirror-1" || running.State != "running" || running.Done == nil || *running.Done != 16.84 || running.ToGo != "02:40:11" {
|
|
t.Errorf("running rebuild: %+v", running)
|
|
}
|
|
if fast.Scrub() != nil {
|
|
t.Errorf("fast has no scrub on record: %+v", fast.Scrub())
|
|
}
|
|
ep := slow.Scans[0]
|
|
if ep.Kind != "error scrub" || ep.State != "paused" || ep.Started == nil || ep.Paused == nil || *ep.Done != 42 {
|
|
t.Errorf("paused error scrub: %+v", ep)
|
|
}
|
|
sp := paused.Scrub()
|
|
if sp == nil || sp.State != "paused" || !sp.Started.Equal(time.Date(2026, 10, 8, 1, 0, 0, 0, time.Local)) ||
|
|
!sp.Paused.Equal(time.Date(2026, 10, 8, 12, 0, 0, 0, time.Local)) || *sp.Done != 43.95 || sp.ToGo != "" {
|
|
t.Errorf("paused scrub: %+v", sp)
|
|
}
|
|
st, _ = ParseStatus(fixture(t, "zpool-status.txt"))
|
|
if s := st[1].Scrub(); s == nil || s.Repaired != "0B" || s.State != "finished" {
|
|
t.Errorf("a finished scrub with a human size: %+v", s)
|
|
}
|
|
st, _ = ParseStatus(fixture(t, "zpool-status-scrubbing.txt"))
|
|
if s := st[0].Scrub(); s == nil || s.Repaired != "0B" || *s.Done != 29.17 {
|
|
t.Errorf("a running scrub: %+v", s)
|
|
}
|
|
if s := parseScan("scan", "scrub in progress since Sun Oct 4 00:24:01 2026\n12.3T / 26.2T scanned, 0B / 26.2T issued\n0B repaired, 0.00% done, no estimated completion time"); s.ToGo != "" || !s.NoEstimate {
|
|
t.Errorf("no estimate: %+v", s)
|
|
}
|
|
}
|
|
|
|
// zpool iostat -H prints no section lines (a blank line stands before each class), and under -p a vdev
|
|
// without capacity stats prints 0 for both.
|
|
func TestIOWithoutSectionLines(t *testing.T) {
|
|
st, _ := ParseStatus(fixture(t, "zpool-status.txt"))
|
|
rows, err := ParseIO(fixture(t, "zpool-iostat.txt"), st)
|
|
if err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
for _, r := range rows {
|
|
if r.Kind == "section" {
|
|
t.Errorf("a section line: %+v", r)
|
|
}
|
|
}
|
|
if len(rows) != 10 || rows[2].Allocated != nil || rows[2].Free != nil || rows[4].Kind != "vdev" || rows[4].Role != "log" ||
|
|
rows[7].Role != "cache" {
|
|
t.Errorf("rows: %+v", rows)
|
|
}
|
|
}
|
|
|
|
// The error counts outlive a restart of the bundle: what was seen before is kept in a small file, so a
|
|
// count that rose while the bundle was down is told from one that was there before.
|
|
func TestTheErrorMemoryIsKeptAcrossARestart(t *testing.T) {
|
|
path := filepath.Join(t.TempDir(), "errors.json")
|
|
f := newFake(t)
|
|
f.errors = LoadErrorMemory(path)
|
|
f.on(line("zpool", PoolsArgv()), "slow\t1000\t100\t900\t10\t1\tONLINE\t1.00\n")
|
|
f.on(line("zpool", StatusArgv()), fixtureSection(t, "zpool-status-rebuild.txt", "slow"))
|
|
if h := f.machine().Health(context.Background()); !h.Healthy {
|
|
t.Fatalf("first look: %+v", h)
|
|
}
|
|
// Restarted: a new memory from the file, and the count rose meanwhile.
|
|
f.errors = LoadErrorMemory(path)
|
|
f.now = f.now.Add(time.Hour)
|
|
f.on(line("zpool", StatusArgv()), strings.Replace(fixtureSection(t, "zpool-status-rebuild.txt", "slow"), "0 0 2", "0 0 9", 1))
|
|
if h := f.machine().Health(context.Background()); h.Healthy || !strings.Contains(h.Why, "checksum errors rose from 2 to 9") {
|
|
t.Errorf("after a restart: %+v", h)
|
|
}
|
|
}
|