diff --git a/modules/zfs/README.md b/modules/zfs/README.md index 84589517..caf68bc0 100644 --- a/modules/zfs/README.md +++ b/modules/zfs/README.md @@ -1,107 +1,201 @@ # zfs The mesh's view of ZFS on a machine: every pool's health, layout, space, scrubs, I/O, cache and events, -every dataset with its space and snapshots, and one act, a named snapshot of one dataset. It is for the -home server, whose pool holds the operator's media library, which the mesh does not own (novox/hq ADR -0051). So the module reads, and the one thing it does only adds. +and every dataset with its space and snapshots. It owns the pool's scrub schedule. It has four acts: a named +snapshot of one dataset, and a scrub's start, pause and stop. It is for the home server, whose pool holds +the operator's media library, which the mesh does not own (novox/hq ADR 0051). So the module reads, and +what it does only adds a snapshot or reads the pool through. ## What it does not do -There is no destroy, rollback, set, send, receive, rename, clone or any other change. Each of those changes -or removes the operator's data and needs a decision of its own first. `zfs_snapshot` is the only tool that -changes anything, and it only adds a snapshot. +There is no destroy, rollback, set, send, receive, rename, clone, replace, attach, detach or clear. Each of +those changes or removes the operator's data, or the pool's layout, and needs a decision of its own first. +A resilver is ZFS's own: it starts one when a disk is replaced or comes back. The module watches and +reports resilvers, and starts none. -This is checked by `TestTheBundleRunsOnlyReadingVerbsAndSnapshot`. Every command the bundle runs is built -by one of its argument functions, and each function is held to its verb: `list`, `get`, `status`, -`iostat`, `events`, `history` or `snapshot`. A call site that builds its own argument list fails the test. +This is checked by `TestTheBundleRunsOnlyReadingVerbsSnapshotAndScrub`. Every command the bundle runs is +built by one of its argument functions, and each function is held to its program and verb: + +- `zfs`: `list`, `get` and `snapshot`; +- `zpool`: `list`, `status`, `iostat`, `events`, `history` and `scrub` (with `-p` or `-s` only); +- `systemctl`: `show`. + +The test fails on any call site that builds its own argument list, through `ask`, `AsRoot`, `Escalated`, +`.Run(`, `exec.Command(`, `exec.CommandContext(`, `os.StartProcess` or `syscall.Exec`. It installs nothing. ZFS belongs to the machine, and its kernel module is built against that machine's kernel. On a machine without ZFS, every tool answers `applicable: false` with the reason, and the health check is unhealthy and says to unassign the module, because a module put where it does nothing must not look healthy. -It holds no seat. A new `node-*` seat is the controller's to define (novox/hq ADR 0121, ADR 0246). This -is a module with tools, like `disk-load` and `sensors`. If the mesh later gives a machine's storage a -seat, these tools become its verbs. +It holds no seat. A new `node-*` seat is the controller's to define (novox/hq ADR 0121, ADR 0246). ## Tools The tools run as the operator account. What ZFS lets any account read runs as that account. What ZFS -keeps for root (events, history and the snapshot itself) goes through `sudo -n` with a fixed argument -list, never a shell. Sizes are whole bytes, read under `-p`, and each answer also says its findings in -lines under `said`. +keeps for root goes through `sudo -n` with a fixed argument list, never a shell: events, history, the +snapshot and the scrub acts. Sizes are whole bytes, read under `-p`, except where status prints human sizes +even under `-p` (a scan's sizes). Each answer also says its findings in lines under `said`. + +A command that runs out of time is ended with everything it started. It runs in a process group of its +own. At the deadline the group gets SIGTERM, which sudo passes on to the command it runs as root, and +after five seconds SIGKILL. An act that ran out of time is answered from what the machine shows afterwards, +or as "outcome unknown". | tool | what | replaces | |---|---|---| -| `zfs_datasets` | Every filesystem and volume: mountpoint, used, available, referenced, compression ratio, sharenfs, and the number of snapshots with the space they hold together (`usedbysnapshots`) | `zfs list` | -| `zfs_snapshots` | The snapshots of one dataset (`dataset`, optional), oldest first: creation time, used (the space only that snapshot holds) and referenced | `zfs list -t snapshot` | +| `zfs_datasets` | Every filesystem and volume: mountpoint, used, available, referenced, compression ratio, sharenfs, and the number of snapshots with the space they hold together | `zfs list` | +| `zfs_snapshots` | The snapshots of one `dataset` (optional), oldest first: creation time, used (the space only that snapshot holds) and referenced | `zfs list -t snapshot` | | `zfs_snapshot` | Takes `dataset@name` (see below) | `zfs snapshot` | -| `zfs_pools` | Each pool's state with status's explanation and action, space, capacity and fragmentation %, device error count, data errors and last scan | `zpool list`, `zpool status -x` | -| `zfs_space` | Each pool's space, then every dataset, biggest first: usedbydataset, usedbysnapshots, usedbychildren and usedbyrefreservation, quotas and reservations where set, compression, logical size against physical size, and the savings | `zfs list -o space`, `zpool list -v` | -| `zfs_pool_layout` | Vdevs and disks by the names the pool knows them by, with state, read, write and checksum errors and status's note; log, cache, special and dedup devices; spares | `zpool status`, `zpool status -v` | -| `zfs_scrub` | The last scan (scrub or resilver): when, how long, what it repaired, the errors, or its progress while it runs; the days since the last finished scrub, with a warning past 35. With `history: true`, it also reads the pool's history (as root) for the scrub and resilver that status no longer shows | `zpool history -i` | +| `zfs_pools` | Each pool's state with status's reason and action, space, capacity and fragmentation %, device error count, data errors and scans | `zpool list`, `zpool status -x` | +| `zfs_space` | Each pool's space, then every dataset, biggest first, with what uses its space, quotas and reservations, compression and the savings | `zfs list -o space`, `zpool list -v` | +| `zfs_pool_layout` | Vdevs and disks, with state, error counts and status's note; log, cache, special and dedup devices; spares | `zpool status`, `zpool status -v` | +| `zfs_scrub` | Each pool's scans: its scrub or error scrub, and its resilver (pool-wide, or each vdev's rebuild), with progress and time to go while one runs; the days since the last finished scrub; and the module's schedule with its next run. `history: true` also reads the pool's history | `zpool history -i` | +| `zfs_scrub_start` | Starts a scrub of `pool`, or resumes a paused one, with `why` | `zpool scrub` | +| `zfs_scrub_pause` | Pauses one, keeping its place, with `why` | `zpool scrub -p` | +| `zfs_scrub_stop` | Stops one, losing its place, with `why` | `zpool scrub -s` | | `zfs_io` | A sample of `seconds` (default 3, from 1 to 10): operations and bytes per second per pool, vdev and disk | `zpool iostat -v` | -| `zfs_arc` | ARC size, target, minimum and maximum, hit ratio since boot, demand hit ratio, and L2ARC where present | `arcstat`, `arc_summary` | -| `zfs_events` | Recent events, newest first, as root. By default it shows only errors and changes of state, and `all: true` shows every event (`limit`, default 50) | `zpool events -v` | -| `zfs_properties` | Every property of one `dataset` with its source, the usual ones in lines first. The value of `keylocation` is withheld, and ZFS never gives a key itself | `zfs get all` | +| `zfs_arc` | ARC size, target, minimum and maximum, hit ratio since boot, and L2ARC where present | `arcstat`, `arc_summary` | +| `zfs_events` | Recent events, newest first, as root. By default it shows only errors and changes of state, and `all: true` shows every event | `zpool events -v` | +| `zfs_properties` | Every property of one `dataset` with its source. The value of `keylocation` is withheld | `zfs get all` | | `zfs_health` | The health check (below) | | ## The snapshot -`zfs_snapshot {dataset, name, why, recursive?}` refuses all of these before anything runs: +`zfs_snapshot {dataset, name, why}` snapshots one dataset, never its children. There is no `recursive`, +and passing one is refused. It refuses all of these before anything runs: - a dataset that `zfs list` does not show on this machine; -- a name with anything but letters, digits, `.`, `_` and `-`; -- a whole name longer than ZFS's 255 characters; -- a snapshot that already exists (with `recursive`, on any child too); +- a name with anything but letters, digits, `.`, `_` and `-`, or a whole name longer than 255 characters; +- a snapshot that already exists; - a missing `why`, or a `why` longer than one line. -It then runs `sudo -n zfs snapshot -- @`, with `-r` only when `recursive` is true. It -answers from `zfs list` afterwards, not from what it ran: the snapshot made and its creation time, and any -other snapshot that came or went during the call (another schedule's, for example). A snapshot the list -does not show is an error, whatever the command said. +It runs `sudo -n zfs snapshot -- @`. It answers from `zfs list` afterwards, not from what +it ran: the snapshot made, its creation time, and any other snapshot that came or went during the call. It +also gives the dataset's free space and the pool's capacity. **From then on, the snapshot holds every block +of the dataset that is deleted or overwritten, so that space is not freed until the snapshot is destroyed by +hand.** No tool of the mesh destroys a snapshot. -The act is recorded as the event `snapshot.taken` (the dataset, the name, why, whether it was done, and -when), and ZFS keeps the command in the pool's own history. An event the bus does not accept is said in -the answer as NOT RECORDED. +The act is recorded as the event `snapshot.taken`, and ZFS keeps the command in the pool's own history. + +## The scrub schedule + +The module owns the schedule of the pool its `scrub-pool` setting names. + +| setting | default | what | +|---|---|---| +| `scrub-pool` | none: the operator's value | the pool to scrub | +| `scrub-cadence` | `weekly` | `weekly`, or `monthly` (the first given weekday of each month) | +| `scrub-day` | `Mon` | `Mon` to `Sun` | +| `scrub-time` | `00:00` | `HH:MM`, in the machine's time zone | + +The defaults are what the distribution's weekly timer did on the home server before the module, so taking +it over does not move the schedule. + +The mesh writes two timer templates of the module's own, `zfs-mesh-scrub-weekly@.timer` and +`zfs-mesh-scrub-monthly@.timer`, and the service they start, `zfs-mesh-scrub@.service`. The service runs +`/usr/bin/zpool scrub -w -- ` with no shell; stopping it while a scrub runs pauses the scrub, as the +distribution's unit does. The mesh enables the one timer the cadence names, for the one pool. + +**Exactly one schedule per pool.** In the same declaration, the distribution's own +`zfs-scrub-weekly@.timer` and `zfs-scrub-monthly@.timer` are held stopped and disabled. On the +home server the weekly one was enabled by hand, outside the mesh. A scrub already running is not stopped by +this; only its timer is. The day and time cannot be expressed with the distribution's templates, which fire +at "weekly" or "monthly" with a random delay, so the module's own timer replaces them. + +**Unassigning the module leaves the pool with no scrub schedule.** The node-engine gives a unit back as it +found it but never starts one on the way out: the distribution's timer stays stopped and disabled, and the +module's own timer and units go. Re-enable a schedule by hand, or assign the module again. + +**One pool per assignment in this version.** A manifest's resources are fixed, and a setting cannot make +one timer per pool in a list. The home server has one pool. A second pool needs either a second set of +resources or a controller feature that makes resources per item of a list. + +The setting values reach the timer file as they are. The tools check them (`zfs_scrub` and the health say +an invalid one), and the service manager refuses a calendar it cannot read. The values are the operator's +own, so they are not escaped. + +### The scrub acts + +`zfs_scrub_start`, `zfs_scrub_pause` and `zfs_scrub_stop` take `{pool, why}`. They refuse a pool that +`zpool list` does not show, and a missing `why`. They run `sudo -n zpool scrub [-p|-s] -- ` and +answer what status says afterwards. Each is recorded as the event `scrub.requested`. + +A scrub reads every block and rewrites, from the pool's redundancy, only a block whose checksum is wrong. +It changes no file's content. It adds read load for its whole length, which on the home server's pool was +about 46 hours for the weekly scrub that ended 2026-10-06. These three are **candidates for the approval +mark** (novox/hq research 039): a person's acts that never change data, and that cost hours of I/O. + +## Resilvers + +ZFS starts a resilver by itself when a disk is replaced or reattached, so there is no schedule to own. The +module watches and reports it: + +- `zfs_scrub` shows a running resilver, pool-wide or a vdev's rebuild, with its progress and the time to go; +- the health check warns while one runs, and is unhealthy when one finished with errors; +- the event follower writes its start and finish to the journal. ## Health -The module runs two long-running processes of its own binary, and neither writes a file or changes -anything: +The module runs two long-running processes of its own binary, and the timer: -- **The watch** (`zfs-tools watch`) carries the module's health check, `zfs_health` (novox/hq ADR 0240). - Each minute it reads the pools and writes a line in its journal whenever their health changes. -- **The event follower** (`zfs-tools events`) runs as root and follows `zpool events -f`. It writes each - error and change of state to its journal as ZFS emits it. ZFS keeps its events in memory only, so they - are lost at a reboot, and the journal keeps them past one. The node-engine judges it by its unit. That - is the check the module does not run itself, which a tool check needs beside it (ADR 0240 rule 2). +- **The watch** (`zfs-tools watch`) runs as the operator account and carries the health check, + `zfs_health` (novox/hq ADR 0240). Each minute it reads the pools and writes a line in its journal whenever + their health changes. +- **The event follower** (`zfs-tools events`) runs as root and follows `zpool events -f`. It is described + in the next section. +- **The scrub timer** is judged by its unit. -`zfs_health` is **unhealthy** when: +`zfs_health` is **unhealthy** for a fault now: -- a pool is not ONLINE (the answer gives status's reason and action); -- a device has read, write or checksum errors, or is not online; -- a pool reports data errors; -- a pool is more than 90 % full; -- no pool is imported; -- ZFS is not on the machine. +- a pool not ONLINE (the answer gives status's reason and action), or a device not online; +- a device's error counts that rose since the last look. A rise stays unhealthy for 15 minutes, so the + node-engine's two looks see it; +- data errors, or a resilver that finished with errors; +- a pool more than 90 % full; +- no pool imported, or no ZFS on the machine. -These are **warnings**, which leave the module healthy: +These are **warnings**, which leave it healthy: -- a pool is more than 80 % full; -- a pool's last scrub finished more than 35 days ago, or the pool was never scrubbed. +- error counts from before ("N past checksum errors; clear them by hand once understood"). The first look + after the bundle starts takes every count as past; +- a pool more than 80 % full; +- a resilver running; +- a last finished scrub older than the schedule allows (weekly 9 days, monthly 38 days), or 35 days for a + pool without a schedule; +- a scheduled scrub that failed, with no scrub finished since; +- a schedule whose timer is not active and enabled, or whose settings are not valid. -The health check judges only the last scan that status shows. If that scan was a resilver, the last -scrub's age is in `zfs_scrub` with `history: true`. +## The event journal + +ZFS keeps its events in a queue in the kernel, in memory, from the moment its module loads, so a reboot +loses them. The follower reads the queue from its oldest event, then follows. So the pool's import, and +whatever came while the follower was down, reach the journal too. It writes each error and change of state +in one line, resilver and scrub starts and ends among them. It also writes ZFS's own "dropped N events" line +when the queue overflowed before it was read. + +A cursor of the boot and the last event read is kept in `/run/zfs-events/cursor`, which a reboot empties as +it empties ZFS's queue. With it, a follower that restarts does not write an event twice. After five +follows in a row that end within a minute, the follower exits non-zero, so the service manager counts the +restarts and the unit's state shows the failure. + +**What survives a reboot** is what reached the journal. That holds where journald keeps its journal on +disk. On the home server it does: its journal is in `/var/log/journal`, and it holds entries from before the +reboot of 2026-10-04 02:09, as read through the mesh on 2026-10-09. Events ZFS emits after the follower has +stopped during a shutdown are lost with the queue. ## Tests -`go test ./...` runs against OpenZFS 2.4 output in `cmd/zfs-tools/testdata`. Each file has the exact form -the command prints, with documentation names in place of the real pools and disks. The tests cover: +`go test ./...` runs against OpenZFS 2.4.4 output in `cmd/zfs-tools/testdata`. Each file has the form that +version's `zpool_main.c` and `libzfs` print, with documentation names in place of the real pools and disks. +The tests cover: -- parsing every command's output; -- the snapshot's argument list, every refusal (none runs a command), the read-back, a snapshot the list - does not show, a refused sudo, an event the bus does not accept, and another snapshot taken meanwhile; -- the health verdicts; +- parsing every command's output, including the scan lines (human sizes, rebuilds per vdev, error scrubs, + paused scrubs) and `iostat -H` without section lines; +- a timed-out command ended with its children; +- the snapshot's refusals, read-back, space statement and unknown outcome; +- the scrub acts and the schedule; +- the follower's cursor, dropped events, kill before wait, and exit after repeated failures; +- the health verdicts, past against new errors; - a machine without ZFS; - the manifest against the tools the bundle serves. diff --git a/modules/zfs/cmd/zfs-tools/events.go b/modules/zfs/cmd/zfs-tools/events.go index 29d04362..0385ee3a 100644 --- a/modules/zfs/cmd/zfs-tools/events.go +++ b/modules/zfs/cmd/zfs-tools/events.go @@ -23,7 +23,8 @@ type Event struct { var eventKeys = map[string]bool{ "pool": true, "pool_state": true, "vdev_path": true, "vdev_type": true, "vdev_state": true, "vdev_laststate": true, "vdev_read_errors": true, "vdev_write_errors": true, "vdev_cksum_errors": true, "zio_err": true, "zio_objset": true, - "zio_object": true, "history_internal_name": true, "history_internal_str": true, "vdev_ashift": true, + "zio_object": true, "history_internal_name": true, "history_internal_str": true, "vdev_ashift": true, "eid": true, + "resilver_type": true, } // vdevStates are ZFS's vdev states as numbers, as events give them. @@ -41,6 +42,9 @@ func ParseEvents(out string) []Event { if strings.TrimSpace(line) == "" { continue } + if droppedLine.MatchString(strings.TrimSpace(line)) { + continue + } if line[0] != ' ' && line[0] != '\t' { f := strings.Fields(line) if len(f) < 2 || (f[0] == "TIME" && f[len(f)-1] == "CLASS") { diff --git a/modules/zfs/cmd/zfs-tools/follow.go b/modules/zfs/cmd/zfs-tools/follow.go index 0fae9297..495316ee 100644 --- a/modules/zfs/cmd/zfs-tools/follow.go +++ b/modules/zfs/cmd/zfs-tools/follow.go @@ -3,25 +3,105 @@ package main import ( "bufio" "context" + "encoding/json" + "errors" "fmt" "io" + "os" "os/exec" + "path/filepath" + "regexp" "sort" + "strconv" "strings" + "syscall" "time" ) -// The module's second long-running process (`zfs-tools events`), run by the node-engine as root. ZFS keeps -// its events in memory only, so a reboot or a reload of its kernel module loses them; the follower writes -// each error and change of state to its journal as ZFS emits it, where it outlives both. It writes no file -// and changes nothing. It is judged by its unit (novox/hq ADR 0240), the check beside zfs_health that the -// module does not run itself. +// The module's second long-running process (`zfs-tools events`), run by the node-engine as root. +// +// ZFS keeps its events in a queue in the kernel, in memory, from the moment its module loads: a reboot +// loses them. `zpool events -f` gives the queue from its oldest event kept, then follows. The follower +// writes each error and change of state (resilver and scrub starts and ends among them) to its journal, so +// they outlive the reboot where the journal is kept on disk. It reads the queue from its start, so the +// pool's import and whatever came while the follower was down reach the journal too; a cursor of the boot +// and the last event read, in CursorFile, keeps it from writing an event twice when it restarts. A line +// ZFS gives when its queue was full and it dropped events is written as it comes. +// +// It writes no other file and changes nothing. It is judged by its unit (novox/hq ADR 0240): after +// MaxFollowFailures follows in a row that end within FollowSettle, it exits non-zero, so the service +// manager's restart counting and the unit's state say so. -// FollowArgv follows ZFS's events as they come, with their details. +// FollowArgv follows ZFS's events from the oldest kept, with their details. func FollowArgv() []string { return []string{"events", "-f", "-v"} } -// FollowRetry is how long the follower waits before following again after zpool exits. -const FollowRetry = 30 * time.Second +// CursorFile is where the follower keeps the boot and the last event it read. Under /run, so a reboot, +// which empties ZFS's queue, empties it too. +const CursorFile = "/run/zfs-events/cursor" + +// BootID names this boot. +const BootID = "/proc/sys/kernel/random/boot_id" + +const ( + // FollowRetry is how long the follower waits before following again after zpool ended. + FollowRetry = 30 * time.Second + // FollowSettle is how long a follow must last to count as having worked. + FollowSettle = time.Minute + // MaxFollowFailures in a row end the follower with an error. + MaxFollowFailures = 5 +) + +// Cursor is the last event read in this boot: its id and its time. ZFS numbers events from its module's +// load, so after a reload a smaller id with a later time is a new event. +type Cursor struct { + Boot string `json:"boot"` + EID uint64 `json:"eid"` + Time time.Time `json:"time"` + path string +} + +// LoadCursor is the cursor kept for this boot; an empty one for another boot or none kept. +func LoadCursor(path, boot string) *Cursor { + c := &Cursor{Boot: boot, path: path} + b, err := os.ReadFile(path) + if err != nil { + return c + } + var kept Cursor + if json.Unmarshal(b, &kept) != nil || kept.Boot != boot { + return c + } + kept.path = path + return &kept +} + +// Save keeps the cursor, atomically. +func (c *Cursor) Save(path string) error { + if path == "" { + return nil + } + if err := os.MkdirAll(filepath.Dir(path), 0o700); err != nil { + return err + } + b, _ := json.Marshal(c) + tmp := path + ".new" + if err := os.WriteFile(tmp, b, 0o600); err != nil { + return err + } + return os.Rename(tmp, path) +} + +// seen says whether an event was read already. +func (c *Cursor) seen(eid uint64, at time.Time, timed bool) bool { + if c.EID == 0 && c.Time.IsZero() { + return false + } + if eid > c.EID { + return false + } + // A smaller or equal id: read, unless it is later than the cursor (ZFS's counter began again). + return !timed || !at.After(c.Time) +} // eventTime reads an event's time as `zpool events` gives it: "Oct 8 2026 21:01:55.889900112". func eventTime(s string) (time.Time, bool) { @@ -43,27 +123,42 @@ func EventLine(e Event) string { return line } -// Follow reads `zpool events -f -v` and writes each notable event at or after since in a line. `-f` first -// gives every event ZFS still keeps; those from before since were written by an earlier follower, or are -// in zfs_events, and are not written again. -func Follow(r io.Reader, out io.Writer, since time.Time) error { +var droppedLine = regexp.MustCompile(`^dropped (\d+) events$`) + +// Follow reads `zpool events -f -v` and writes each notable event the cursor has not seen in a line, and +// each line saying ZFS dropped events; the cursor moves past every event read and is saved as it goes. +func Follow(r io.Reader, out io.Writer, cur *Cursor) error { sc := bufio.NewScanner(r) sc.Buffer(make([]byte, 64*1024), 1024*1024) var block []string flush := func() { + if len(block) == 0 { + return + } for _, e := range ParseEvents(strings.Join(block, "\n")) { - if !Notable(e.Class) { + at, timed := eventTime(e.Time) + eid, _ := strconv.ParseUint(strings.TrimPrefix(e.Details["eid"], "0x"), 16, 64) + if cur.seen(eid, at, timed) { continue } - if t, ok := eventTime(e.Time); ok && t.Before(since) { - continue + if Notable(e.Class) { + fmt.Fprintln(out, EventLine(e)) } - fmt.Fprintln(out, EventLine(e)) + cur.EID = eid + if timed { + cur.Time = at + } + _ = cur.Save(cur.path) } block = block[:0] } for sc.Scan() { l := sc.Text() + if m := droppedLine.FindStringSubmatch(strings.TrimSpace(l)); m != nil { + flush() + fmt.Fprintf(out, "ZFS dropped %s events before they were read: its queue was full\n", m[1]) + continue + } if strings.TrimSpace(l) == "" { flush() continue @@ -74,31 +169,101 @@ func Follow(r io.Reader, out io.Writer, since time.Time) error { return sc.Err() } -// Follower runs zpool events -f until the context ends, again after FollowRetry whenever it exits. -func Follower(ctx context.Context, out io.Writer) { - since := time.Now() +// FollowProcess is a running `zpool events -f`. +type FollowProcess interface { + Stdout() io.Reader + Kill() error + Wait() error +} + +// FollowOnce follows until zpool ends or its output cannot be read. On a failure to read, zpool is +// killed before it is waited for: it would otherwise follow on, and the wait never end. +func FollowOnce(p FollowProcess, out io.Writer, cur *Cursor) error { + ferr := Follow(p.Stdout(), out, cur) + if ferr != nil { + _ = p.Kill() + } + werr := p.Wait() + if ferr != nil { + return fmt.Errorf("reading zpool events: %w", ferr) + } + if werr != nil { + return fmt.Errorf("zpool events -f ended: %w", werr) + } + return errors.New("zpool events -f ended") +} + +// RunFollower follows again after each end, and gives up with an error after MaxFollowFailures follows in +// a row that did not last FollowSettle. +func RunFollower(ctx context.Context, out io.Writer, start func(context.Context) (FollowProcess, error), cur *Cursor, + cursorPath string, wait func(time.Duration)) error { + if cursorPath != "" { + cur.path = cursorPath + } + failures := 0 for ctx.Err() == nil { - cmd := exec.CommandContext(ctx, "zpool", FollowArgv()...) - stdout, err := cmd.StdoutPipe() - if err == nil { - err = cmd.Start() - } - if err == nil { - err = Follow(stdout, out, since) - if werr := cmd.Wait(); err == nil { - err = werr - } + began := time.Now() + var err error + p, serr := start(ctx) + if serr != nil { + err = serr + } else { + err = FollowOnce(p, out, cur) } if ctx.Err() != nil { - return + return nil } - fmt.Fprintf(out, "zpool events -f stopped (%v); following again in %s\n", err, FollowRetry) - // What comes while it waits is still in ZFS's own list, and the next follow writes it from here. - since = time.Now() + if time.Since(began) >= FollowSettle { + failures = 0 + } + failures++ + fmt.Fprintf(out, "following ZFS's events stopped (%v); %d of %d in a row\n", err, failures, MaxFollowFailures) + if failures >= MaxFollowFailures { + return fmt.Errorf("following ZFS's events failed %d times in a row, the last: %v", failures, err) + } + wait(FollowRetry) + } + return nil +} + +// zpoolFollow is the real `zpool events -f -v`, in a process group of its own. +type zpoolFollow struct { + cmd *exec.Cmd + out io.ReadCloser +} + +func (z *zpoolFollow) Stdout() io.Reader { return z.out } +func (z *zpoolFollow) Kill() error { return syscall.Kill(-z.cmd.Process.Pid, syscall.SIGKILL) } +func (z *zpoolFollow) Wait() error { return z.cmd.Wait() } + +// StartZpoolFollow starts `zpool events -f -v`; the context's end kills it. +func StartZpoolFollow(ctx context.Context) (FollowProcess, error) { + cmd := exec.Command("zpool", FollowArgv()...) + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + cmd.WaitDelay = KillGrace + out, err := cmd.StdoutPipe() + if err != nil { + return nil, err + } + if err := cmd.Start(); err != nil { + return nil, err + } + z := &zpoolFollow{cmd: cmd, out: out} + go func() { + <-ctx.Done() + _ = z.Kill() + }() + return z, nil +} + +// Follower is the events process: the cursor for this boot, then RunFollower. +func Follower(ctx context.Context, out io.Writer) error { + boot, _ := os.ReadFile(BootID) + cur := LoadCursor(CursorFile, strings.TrimSpace(string(boot))) + return RunFollower(ctx, out, StartZpoolFollow, cur, CursorFile, func(d time.Duration) { select { case <-ctx.Done(): - return - case <-time.After(FollowRetry): + case <-time.After(d): } - } + }) } diff --git a/modules/zfs/cmd/zfs-tools/health.go b/modules/zfs/cmd/zfs-tools/health.go index 633eff86..32d20d1b 100644 --- a/modules/zfs/cmd/zfs-tools/health.go +++ b/modules/zfs/cmd/zfs-tools/health.go @@ -23,14 +23,73 @@ type Health struct { Warnings []string `json:"warnings,omitempty"` } -// Judge judges the pools from what zpool list and zpool status said. -func Judge(pools []Pool, status []PoolStatus, now time.Time) Health { +// ErrorsFresh is how long a rise in a device's error counts keeps the health unhealthy: long enough for +// the node-engine's two looks to see it, and a condition to be raised. +const ErrorsFresh = 15 * time.Minute + +// Look is what one health check read. +type Look struct { + Pools []Pool + Status []PoolStatus + Now time.Time + Schedule *Schedule + // ScheduleErr is a schedule whose settings are not valid. + ScheduleErr error +} + +// errorFinding judges one line of status's error counts against the last look: a count that rose is a +// fault now; a count that was there before is past, a warning to clear by hand once understood. +func (mem *ErrorMemory) errorFinding(pool string, d *Device, now time.Time) (fault, past string) { + key := pool + "/" + d.Kind + "/" + d.Name + counts := [3]uint64{d.Read, d.Write, d.Checksum} + names := [3]string{"read", "write", "checksum"} + if mem == nil { + mem = NewErrorMemory() + } + mem.mu.Lock() + defer mem.mu.Unlock() + before, seen := mem.counts[key] + mem.counts[key] = counts + var rose []string + for i := range counts { + if seen && counts[i] > before[i] { + rose = append(rose, fmt.Sprintf("%s errors rose from %d to %d", names[i], before[i], counts[i])) + } + } + if len(rose) > 0 { + mem.rose[key] = now + return fmt.Sprintf("%s %s in pool %s: %s since the last look.", d.Kind, d.Name, pool, strings.Join(rose, ", ")), "" + } + if at, ok := mem.rose[key]; ok && now.Sub(at) < ErrorsFresh { + return fmt.Sprintf("%s %s in pool %s: its errors rose at %s (read %d, write %d, checksum %d).", d.Kind, d.Name, pool, + at.Local().Format("15:04"), d.Read, d.Write, d.Checksum), "" + } + if d.Errors() == 0 { + return "", "" + } + var parts []string + for i := range counts { + if counts[i] > 0 { + parts = append(parts, fmt.Sprintf("%d past %s errors", counts[i], names[i])) + } + } + return "", fmt.Sprintf("%s %s in pool %s has %s; clear them by hand once understood.", d.Kind, d.Name, pool, strings.Join(parts, " and ")) +} + +// Judge judges the pools from what one look read. Unhealthy is a fault now: a pool or device not online, +// error counts that rose, data errors, a pool past CapacityFail, a resilver that finished with errors. +// A warning is a past fault or a risk: error counts that were there before, a pool past CapacityWarn, a +// resilver running, a scrub later than its schedule allows, a schedule that failed or does not run. +func (mem *ErrorMemory) Judge(l Look) Health { var found, warn []string - if len(pools) == 0 { + if len(l.Pools) == 0 { found = append(found, "ZFS is on this machine and no pool is imported.") } - for _, p := range pools { - s := statusOf(status, p.Name) + if l.ScheduleErr != nil { + warn = append(warn, sentence("the scrub schedule's settings are not valid: "+l.ScheduleErr.Error())) + } + for _, p := range l.Pools { + s := statusOf(l.Status, p.Name) state := p.Health if s != nil && s.State != "" { state = s.State @@ -59,8 +118,12 @@ func Judge(pools []Pool, status []PoolStatus, now time.Time) Health { if d.Kind == "section" { return } - if d.Errors() > 0 { - found = append(found, fmt.Sprintf("%s %s in pool %s has errors: read %d, write %d, checksum %d.", d.Kind, d.Name, p.Name, d.Read, d.Write, d.Checksum)) + fault, past := mem.errorFinding(p.Name, d, l.Now) + if fault != "" { + found = append(found, sentence(fault)) + } + if past != "" { + warn = append(warn, sentence(past)) } if d.Kind != "pool" && d.State != "" && d.State != "ONLINE" && d.State != "AVAIL" && d.State != "INUSE" { // A device not online already makes its pool DEGRADED or worse; said here by name. @@ -70,20 +133,53 @@ func Judge(pools []Pool, status []PoolStatus, now time.Time) Health { if e := strings.TrimSpace(s.Errors); e != "" && e != "No known data errors" { found = append(found, fmt.Sprintf("Pool %s: %s.", p.Name, strings.TrimSuffix(e, "."))) } - if ended := LastScrubEnded(s.Scan); ended != nil && now.Sub(*ended) > ScrubWarnAfter { - warn = append(warn, fmt.Sprintf("Pool %s was last scrubbed %.0f days ago, more than %d.", p.Name, now.Sub(*ended).Hours()/24, int(ScrubWarnAfter.Hours()/24))) - } else if s.Scan.State == "none" { + for _, r := range s.Resilvers() { + what := "the resilver" + if r.Vdev != "" { + what += " of " + r.Vdev + } + switch { + case r.State == "running": + line := fmt.Sprintf("A resilver") + if r.Vdev != "" { + line += " of " + r.Vdev + } + line += fmt.Sprintf(" in pool %s is running", p.Name) + if r.Done != nil { + line += fmt.Sprintf(": %.2f %% done", *r.Done) + } + if r.ToGo != "" { + line += ", " + r.ToGo + " to go" + } + warn = append(warn, sentence(strings.ToLower(line[:1])+line[1:])) + case r.State == "finished" && deref(r.Errors) > 0: + found = append(found, sentence(fmt.Sprintf("%s in pool %s finished with %d errors, %s", what, p.Name, deref(r.Errors), stamp(r.Ended)))) + } + } + late, by := ScrubLate(p.Name, l.Schedule) + ended := LastScrubEnded(*s) + switch { + case ended != nil && l.Now.Sub(*ended) > late: + warn = append(warn, fmt.Sprintf("Pool %s was last scrubbed %.0f days ago, more than %s (%d days).", p.Name, + l.Now.Sub(*ended).Hours()/24, by, int(late.Hours()/24))) + case len(s.Scans) == 0: warn = append(warn, fmt.Sprintf("Pool %s was never scrubbed.", p.Name)) } + if l.Schedule != nil && l.Schedule.Pool == p.Name { + warn = append(warn, scheduleFindings(l.Schedule, ended)...) + } + } + 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 len(found) > 0 { return Health{Healthy: false, Why: strings.Join(found, " "), Found: found, Warnings: warn} } var parts []string - for _, p := range pools { + for _, p := range l.Pools { parts = append(parts, fmt.Sprintf("%s ONLINE, %d %% full", p.Name, p.Capacity)) } - why := "Every pool is online with no errors: " + strings.Join(parts, "; ") + "." + why := "Every pool is online with no new errors: " + strings.Join(parts, "; ") + "." if len(warn) > 0 { why += " Warnings: " + strings.Join(warn, " ") } @@ -104,7 +200,8 @@ func (m *Machine) Health(ctx context.Context) Health { if err != nil { return Health{Healthy: false, Why: sentence("zpool status did not answer: " + err.Error()), Found: []string{err.Error()}} } - return Judge(pools, status, m.Now()) + sched, serr := m.ScheduleNow(ctx) + return m.Errors.Judge(Look{Pools: pools, Status: status, Now: m.Now(), Schedule: sched, ScheduleErr: serr}) } func sentence(s string) string { diff --git a/modules/zfs/cmd/zfs-tools/health_test.go b/modules/zfs/cmd/zfs-tools/health_test.go index ba80be9d..875d8ae7 100644 --- a/modules/zfs/cmd/zfs-tools/health_test.go +++ b/modules/zfs/cmd/zfs-tools/health_test.go @@ -5,7 +5,6 @@ import ( "context" "strings" "testing" - "time" ) func TestOnlinePoolsWithoutErrorsAreHealthyAndAnOldScrubIsOnlyAWarning(t *testing.T) { @@ -13,7 +12,7 @@ func TestOnlinePoolsWithoutErrorsAreHealthyAndAnOldScrubIsOnlyAWarning(t *testin if !h.Healthy || len(h.Found) != 0 { t.Fatalf("health: %+v", h) } - if len(h.Warnings) != 1 || !strings.Contains(h.Warnings[0], "Pool rpool was last scrubbed 89 days ago, more than 35") { + if len(h.Warnings) != 1 || !strings.Contains(h.Warnings[0], "Pool rpool was last scrubbed 89 days ago, more than the module's line for a pool without a schedule (35 days)") { t.Errorf("rpool's July scrub is a warning; tank's September one is not: %v", h.Warnings) } if !strings.Contains(h.Why, "tank ONLINE, 60 % full") { @@ -33,7 +32,6 @@ func TestADegradedFullPoolIsUnhealthyWithEveryReason(t *testing.T) { "Pool tank is DEGRADED: One or more devices is currently being resilvered", "Action: Wait for the resilver to complete", "Pool tank is 91 % full, past 90 %", - "device ata-WDC_WD120EFBX-68B0EN0_D7JA0002 in pool tank has errors: read 12, write 107, checksum 3", "device ata-WDC_WD120EFBX-68B0EN0_D7JA0002 in pool tank is FAULTED", "Pool tank: 2 data errors", } { @@ -41,6 +39,9 @@ func TestADegradedFullPoolIsUnhealthyWithEveryReason(t *testing.T) { t.Errorf("why lacks %q: %s", want, h.Why) } } + if !strings.Contains(strings.Join(h.Warnings, " "), "ata-WDC_WD120EFBX-68B0EN0_D7JA0002 in pool tank has 12 past read errors and 107 past write errors and 3 past checksum errors") { + t.Errorf("its counts on a first look are past: %v", h.Warnings) + } if strings.Contains(h.Why, "D7JA0009 in pool tank is") { t.Errorf("a spare in use is not a finding: %s", h.Why) } @@ -50,27 +51,27 @@ func TestCapacityPastEightyIsAWarningAndPastNinetyUnhealthy(t *testing.T) { st, _ := ParseStatus(fixture(t, "zpool-status-scrubbing.txt")) now := newFake(t).now p := Pool{Name: "tank", Capacity: 85, Health: "ONLINE"} - if h := Judge([]Pool{p}, st, now); !h.Healthy || len(h.Warnings) != 1 || !strings.Contains(h.Warnings[0], "85 % full, past 80 %") { + if h := NewErrorMemory().Judge(Look{Pools: []Pool{p}, Status: st, Now: now}); !h.Healthy || len(h.Warnings) != 1 || !strings.Contains(h.Warnings[0], "85 % full, past 80 %") { t.Errorf("85 %%: %+v", h) } p.Capacity = 80 - if h := Judge([]Pool{p}, st, now); !h.Healthy || len(h.Warnings) != 0 { + if h := NewErrorMemory().Judge(Look{Pools: []Pool{p}, Status: st, Now: now}); !h.Healthy || len(h.Warnings) != 0 { t.Errorf("80 %% is not past 80: %+v", h) } p.Capacity = 92 - if h := Judge([]Pool{p}, st, now); h.Healthy { + if h := NewErrorMemory().Judge(Look{Pools: []Pool{p}, Status: st, Now: now}); h.Healthy { t.Errorf("92 %%: %+v", h) } } func TestFaultedAndNoPoolAreUnhealthy(t *testing.T) { now := newFake(t).now - if h := Judge(nil, nil, now); h.Healthy || !strings.Contains(h.Why, "no pool is imported") { + if h := NewErrorMemory().Judge(Look{Now: now}); h.Healthy || !strings.Contains(h.Why, "no pool is imported") { t.Errorf("no pool: %+v", h) } st := []PoolStatus{{Name: "tank", State: "FAULTED", Status: "One or more devices could not be opened.", Errors: "No known data errors", Root: &Device{Name: "tank", Kind: "pool", State: "FAULTED"}}} - if h := Judge([]Pool{{Name: "tank", Health: "FAULTED"}}, st, now); h.Healthy || !strings.Contains(h.Why, "Pool tank is FAULTED: One or more devices could not be opened") { + if h := NewErrorMemory().Judge(Look{Pools: []Pool{{Name: "tank", Health: "FAULTED"}}, Status: st, Now: now}); h.Healthy || !strings.Contains(h.Why, "Pool tank is FAULTED: One or more devices could not be opened") { t.Errorf("faulted: %+v", h) } } @@ -81,7 +82,7 @@ func TestTheWatchSaysOnlyChanges(t *testing.T) { w := &Watch{M: f.machine(), Out: &out} w.Look(context.Background()) w.Look(context.Background()) - if n := strings.Count(out.String(), "\n"); n != 1 || !strings.Contains(out.String(), "healthy: Every pool is online") { + if n := strings.Count(out.String(), "\n"); n != 1 || !strings.Contains(out.String(), "healthy: Every pool is online with no new errors") { t.Errorf("one line for one state: %q", out.String()) } f.on(line("zpool", StatusArgv()), fixture(t, "zpool-status-degraded.txt")) @@ -91,23 +92,19 @@ func TestTheWatchSaysOnlyChanges(t *testing.T) { } } -func TestTheFollowerWritesEachNotableEventFromItsStartOnce(t *testing.T) { - var out bytes.Buffer - since := time.Date(2026, 10, 8, 21, 0, 0, 0, time.Local) - if err := Follow(strings.NewReader(fixture(t, "zpool-events.txt")), &out, since); err != nil { - t.Fatal(err) - } - got := strings.Split(strings.TrimSpace(out.String()), "\n") - if len(got) != 3 || !strings.Contains(got[0], "ereport.fs.zfs.io") || !strings.Contains(got[1], "vdev_state=FAULTED") || - !strings.Contains(got[2], "resilver_start") { - t.Errorf("lines: %q", got) - } - out.Reset() - Follow(strings.NewReader(fixture(t, "zpool-events.txt")), &out, time.Date(2026, 10, 8, 21, 2, 10, 0, time.Local)) - if got := strings.TrimSpace(out.String()); strings.Count(got, "\n") != 0 || !strings.Contains(got, "resilver_start") { - t.Errorf("only what came after since: %q", got) - } +func TestTheFollowerArgvAndAResilverStartAndFinishAreJournaled(t *testing.T) { if strings.Join(FollowArgv(), " ") != "events -f -v" { t.Errorf("argv: %v", FollowArgv()) } + for _, c := range []string{"sysevent.fs.zfs.resilver_start", "sysevent.fs.zfs.resilver_finish", "sysevent.fs.zfs.scrub_start", + "sysevent.fs.zfs.scrub_finish", "resource.fs.zfs.statechange", "ereport.fs.zfs.checksum"} { + if !Notable(c) { + t.Errorf("%s is not journaled", c) + } + } + var out bytes.Buffer + Follow(strings.NewReader(fixture(t, "zpool-events.txt")), &out, &Cursor{}) + if !strings.Contains(out.String(), "sysevent.fs.zfs.resilver_start eid=0x14 pool=tank resilver_type=healing") { + t.Errorf("the resilver's start: %q", out.String()) + } } diff --git a/modules/zfs/cmd/zfs-tools/helpers_test.go b/modules/zfs/cmd/zfs-tools/helpers_test.go index 1a4c4f28..e9da5b0c 100644 --- a/modules/zfs/cmd/zfs-tools/helpers_test.go +++ b/modules/zfs/cmd/zfs-tools/helpers_test.go @@ -34,11 +34,12 @@ type fake struct { files map[string]string now time.Time uid int + errors *ErrorMemory } func newFake(t *testing.T) *fake { return &fake{t: t, answers: map[string]Ran{}, after: map[string]func(*fake){}, files: map[string]string{}, - now: time.Date(2026, 10, 9, 12, 0, 0, 0, time.Local), uid: 1000} + now: time.Date(2026, 10, 9, 12, 0, 0, 0, time.Local), uid: 1000, errors: NewErrorMemory()} } func (f *fake) on(line string, out string) { f.answers[line] = Ran{Out: out} } @@ -69,6 +70,7 @@ func (f *fake) machine() *Machine { } return []byte(s), nil }, + Errors: f.errors, Emit: func(eventType string, body any) error { if f.emitErr != nil { return f.emitErr diff --git a/modules/zfs/cmd/zfs-tools/io.go b/modules/zfs/cmd/zfs-tools/io.go index 0073b512..9ccf2024 100644 --- a/modules/zfs/cmd/zfs-tools/io.go +++ b/modules/zfs/cmd/zfs-tools/io.go @@ -15,12 +15,15 @@ func IOArgv(seconds int) []string { return []string{"iostat", "-y", "-Hpv", strconv.Itoa(seconds), "1"} } -// IORow is one line of the sample: a pool, a vdev, a device or a section. +// IORow is one line of the sample: a pool, a vdev or a device. type IORow struct { Name string `json:"name"` Pool string `json:"pool"` - // Kind is pool, vdev, device or section, from the pool's layout. - Kind string `json:"kind"` + // Kind is pool, vdev or device, and Role data, log, cache, special or dedup, from the pool's layout: + // iostat -H prints no section lines and no indentation. + Kind string `json:"kind"` + Role string `json:"role,omitempty"` + // Allocated and Free are a top-level vdev's; a vdev without capacity of its own has neither. Allocated *uint64 `json:"allocated_bytes,omitempty"` Free *uint64 `json:"free_bytes,omitempty"` ReadOps float64 `json:"read_ops_per_s"` @@ -30,8 +33,9 @@ type IORow struct { } // ParseIO reads `zpool iostat -Hpv`: name, allocated, free, read and write operations, read and write -// bandwidth, tab-separated; "-" where a line has no such number. Lines of a pool follow the pool's own -// line; layout names each line's kind. +// bandwidth, tab-separated. Under -H there are no section lines (a blank line stands before each class) +// and under -p a vdev without capacity of its own prints 0 for both (zpool_main.c, print_iostat_default). +// Lines of a pool follow the pool's own line; its layout names each line's kind and role. func ParseIO(out string, layout []PoolStatus) ([]IORow, error) { var rows []IORow pool := "" @@ -43,25 +47,24 @@ func ParseIO(out string, layout []PoolStatus) ([]IORow, error) { if len(f) != 7 { return nil, fmt.Errorf("zpool iostat answered a line with %d columns, not 7: %q", len(f), line) } - r := IORow{Name: strings.TrimSpace(f[0])} + r := IORow{Name: strings.TrimSpace(f[0]), Kind: "device"} if statusOf(layout, r.Name) != nil { pool = r.Name - r.Kind = "pool" + r.Kind = "" } r.Pool = pool if r.Kind == "" { - r.Kind = "device" - if _, ok := sections[r.Name]; ok && allDash(f[1:]) { - r.Kind = "section" - } else if p := statusOf(layout, pool); p != nil { - walk(p.Root, func(d *Device, _ int) { - if d.Name == r.Name && d.Kind != "pool" { - r.Kind = d.Kind - } - }, 0) - } + r.Kind = "pool" + } else if p := statusOf(layout, pool); p != nil { + walk(p.Root, func(d *Device, _ int) { + if d.Name == r.Name && d.Kind != "pool" && d.Kind != "section" { + r.Kind, r.Role = d.Kind, d.Role + } + }, 0) + } + if !(f[1] == "0" && f[2] == "0") { + r.Allocated, r.Free = optionalNumber(f[1]), optionalNumber(f[2]) } - r.Allocated, r.Free = optionalNumber(f[1]), optionalNumber(f[2]) vals := []*float64{&r.ReadOps, &r.WriteOps, &r.ReadBytes, &r.WriteBytes} for i, v := range vals { s := f[3+i] @@ -79,15 +82,6 @@ func ParseIO(out string, layout []PoolStatus) ([]IORow, error) { return rows, nil } -func allDash(f []string) bool { - for _, s := range f { - if strings.TrimSpace(s) != "-" { - return false - } - } - return true -} - func optionalNumber(s string) *uint64 { if s == "-" { return nil @@ -125,11 +119,11 @@ func (m *Machine) IO(ctx context.Context, seconds int) (any, error) { } a := IOAnswer{Applicable: true, Seconds: seconds, Rows: rows, Said: []string{}} for _, r := range rows { - if r.Kind == "section" { - a.Said = append(a.Said, r.Pool+" "+r.Name+":") - continue + kind := r.Kind + if r.Role != "" && r.Role != "data" { + kind += ", " + r.Role } - a.Said = append(a.Said, fmt.Sprintf("%s %s (%s): read %.0f ops/s %s/s, write %.0f ops/s %s/s", r.Pool, r.Name, r.Kind, + a.Said = append(a.Said, fmt.Sprintf("%s %s (%s): read %.0f ops/s %s/s, write %.0f ops/s %s/s", r.Pool, r.Name, kind, r.ReadOps, bytesSaid(uint64(r.ReadBytes)), r.WriteOps, bytesSaid(uint64(r.WriteBytes)))) } return a, nil diff --git a/modules/zfs/cmd/zfs-tools/machine.go b/modules/zfs/cmd/zfs-tools/machine.go index 95c115a0..3a163a64 100644 --- a/modules/zfs/cmd/zfs-tools/machine.go +++ b/modules/zfs/cmd/zfs-tools/machine.go @@ -8,6 +8,8 @@ import ( "os" "os/exec" "strings" + "sync" + "syscall" "time" ) @@ -23,11 +25,18 @@ import ( // CommandTimeout bounds every command but a sample. const CommandTimeout = 30 * time.Second +// KillGrace is how long a command that ran out of time is given to end on SIGTERM before its whole +// process group is killed. +var KillGrace = 5 * time.Second + // Ran is what one command did. type Ran struct { Out string Err string Code int + // TimedOut is a command that did not answer within its time and was ended: what it did is not known + // from its answer, only from reading the machine again. + TimedOut bool } // Runner runs one command; injected, so every tool is tested over recorded answers. @@ -35,20 +44,49 @@ type Runner func(ctx context.Context, name string, args ...string) Ran // ExecRunner runs a command on the machine, bounded by the context (CommandTimeout unless the caller set // one). +// +// **A command that runs out of time is ended with everything it started.** It runs in a process group of +// its own; at the deadline the group is sent SIGTERM, and after KillGrace SIGKILL. Under sudo the command +// itself runs as root, which this account cannot signal: SIGTERM reaches sudo, which passes it on to the +// command, and the group's SIGKILL ends sudo. The output pipes are closed after KillGrace whatever still +// holds them, so the call always returns. func ExecRunner(ctx context.Context, name string, args ...string) Ran { if _, has := ctx.Deadline(); !has { var cancel context.CancelFunc ctx, cancel = context.WithTimeout(ctx, CommandTimeout) defer cancel() } - cmd := exec.CommandContext(ctx, name, args...) + cmd := exec.Command(name, args...) + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + cmd.WaitDelay = KillGrace var stdout, stderr bytes.Buffer cmd.Stdout, cmd.Stderr = &stdout, &stderr - err := cmd.Run() - r := Ran{Out: stdout.String(), Err: strings.TrimSpace(stderr.String())} + if err := cmd.Start(); err != nil { + return Ran{Code: -1, Err: err.Error()} + } + done := make(chan error, 1) + go func() { done <- cmd.Wait() }() + var err error + timedOut := false + select { + case err = <-done: + case <-ctx.Done(): + timedOut = true + pgid := cmd.Process.Pid + _ = syscall.Kill(-pgid, syscall.SIGTERM) + select { + case err = <-done: + case <-time.After(KillGrace): + _ = syscall.Kill(-pgid, syscall.SIGKILL) + err = <-done + } + // Anything of the group still alive and signalable goes with it. + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + r := Ran{Out: stdout.String(), Err: strings.TrimSpace(stderr.String()), TimedOut: timedOut} if err != nil { var exit *exec.ExitError - if errors.As(err, &exit) { + if errors.As(err, &exit) && !timedOut { r.Code = exit.ExitCode() } else { r.Code = -1 @@ -56,10 +94,10 @@ func ExecRunner(ctx context.Context, name string, args ...string) Ran { r.Err = err.Error() } } - if ctx.Err() != nil { - r.Code = -1 - r.Err = fmt.Sprintf("did not answer within its time (%v)", ctx.Err()) - } + } + if timedOut { + r.Code = -1 + r.Err = strings.TrimSpace(fmt.Sprintf("did not answer within its time and was ended. %s", r.Err)) } return r } @@ -74,11 +112,14 @@ type Machine struct { ReadFile func(path string) ([]byte, error) // Emit publishes an event as this module (the record of an act); nil where nothing can be published. Emit func(eventType string, body any) error + // Errors is what the health check last saw of each device's error counts; nil judges every count + // as past. + Errors *ErrorMemory } // Here is the machine this process runs on. func Here() *Machine { - return &Machine{Run: ExecRunner, UID: os.Getuid(), Now: time.Now, ReadFile: os.ReadFile} + return &Machine{Run: ExecRunner, UID: os.Getuid(), Now: time.Now, ReadFile: os.ReadFile, Errors: NewErrorMemory()} } // NotApplicable is the answer of a machine without ZFS: the module does not apply here. @@ -105,6 +146,27 @@ type errAbsent struct{ why string } func (e errAbsent) Error() string { return e.why } +// errTimedOut is an act that did not answer within its time and was ended: whether it took effect is +// known only by reading the machine again. +type errTimedOut struct{ what string } + +func (e errTimedOut) Error() string { + return e.what + " did not answer within its time and was ended; whether it took effect is not known" +} + +// ErrorMemory is what the health check last saw of each device's error counts, so a count that rises is +// told from one that was there before (a fault now, against a fault past). +type ErrorMemory struct { + mu sync.Mutex + counts map[string][3]uint64 + rose map[string]time.Time +} + +// NewErrorMemory remembers nothing yet: every count on the first look is past. +func NewErrorMemory() *ErrorMemory { + return &ErrorMemory{counts: map[string][3]uint64{}, rose: map[string]time.Time{}} +} + // ask runs a read-only command as this account and answers its output, or why it could not. func (m *Machine) ask(ctx context.Context, name string, args ...string) (string, error) { r := m.Run(ctx, name, args...) @@ -130,6 +192,9 @@ func (m *Machine) Escalated(name string, args ...string) (string, []string) { func (m *Machine) AsRoot(ctx context.Context, name string, args ...string) (Ran, error) { program, argv := m.Escalated(name, args...) r := m.Run(ctx, program, argv...) + if r.TimedOut { + return r, errTimedOut{name + " " + strings.Join(args, " ")} + } if r.Code != 0 { why := orOut(r) if why2 := absent(r); why2 != "" && program != "sudo" { diff --git a/modules/zfs/cmd/zfs-tools/main.go b/modules/zfs/cmd/zfs-tools/main.go index f1ba8ab7..47d93c4e 100644 --- a/modules/zfs/cmd/zfs-tools/main.go +++ b/modules/zfs/cmd/zfs-tools/main.go @@ -25,9 +25,12 @@ func main() { defer stop() switch os.Args[1] { case "watch": - (&Watch{M: Here(), Out: os.Stdout}).Run(ctx) + (&Watch{M: Here(), Out: os.Stdout}).Loop(ctx) case "events": - Follower(ctx, os.Stdout) + if err := Follower(ctx, os.Stdout); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } default: fmt.Fprintf(os.Stderr, "zfs-tools: %q is not a way to run; with no argument it serves its tools, with watch it "+ "watches the pools, with events it follows ZFS's events\n", os.Args[1]) diff --git a/modules/zfs/cmd/zfs-tools/manifest_test.go b/modules/zfs/cmd/zfs-tools/manifest_test.go index 4fae4d80..e3774375 100644 --- a/modules/zfs/cmd/zfs-tools/manifest_test.go +++ b/modules/zfs/cmd/zfs-tools/manifest_test.go @@ -40,7 +40,7 @@ func TestTheManifestNamesTheToolsTheBundleServesAndWhatEachReplaces(t *testing.T for _, tl := range Tools(newFake(t).machine()) { served = append(served, tl.Name) want := "(r)" - if tl.Name == "zfs_snapshot" { + if tl.Name == "zfs_snapshot" || strings.HasPrefix(tl.Name, "zfs_scrub_") { want = "(a)" } if !strings.HasSuffix(tl.Description, want) { @@ -67,7 +67,7 @@ func TestTheManifestNamesTheToolsTheBundleServesAndWhatEachReplaces(t *testing.T if len(m.Claims) != 0 { t.Errorf("the module claims no seat: %v", m.Claims) } - if strings.Join(m.Emits, ",") != SnapshotEvent { + if strings.Join(m.Emits, ",") != SnapshotEvent+","+ScrubEvent { t.Errorf("emits %v", m.Emits) } if hit := regexp.MustCompile(`\b(g14|novox|ace|shanks|jochen)\b|/home/`).FindString(strings.ReplaceAll(raw, "novox/hq", "")); hit != "" { @@ -75,50 +75,125 @@ func TestTheManifestNamesTheToolsTheBundleServesAndWhatEachReplaces(t *testing.T } } -// ADR 0240: the health is zfs_health on the watch, beside the event follower's unit, which the module does -// not judge itself; the module installs nothing, so it never puts ZFS on a machine. -func TestTheHealthIsTheWatchsToolCheckBesideTheFollowersUnit(t *testing.T) { +// ADR 0240: zfs_health on the watch, which runs as the operator account; the follower and the scrub +// timer judged by their units. The module installs nothing, so it never puts ZFS on a machine. +func TestTheHealthChecksAndWhoRunsWhat(t *testing.T) { m, raw := readManifest(t) byID := map[string]map[string]any{} for _, r := range m.Resources { byID[r["id"].(string)] = r } - if len(byID) != 2 { - t.Fatalf("resources: %v", m.Resources) + w := byID["watch"] + if h, _ := w["health"].(map[string]any); h["kind"] != "tool" || h["tool"] != "zfs_health" || w["user"] != "${machine:account}" { + t.Errorf("the watch runs as the operator account and carries zfs_health: %v", w) } - for id, want := range map[string][2]string{"watch": {"tool", "watch"}, "events": {"unit", "events"}} { - r := byID[id] - h, _ := r["health"].(map[string]any) - run, _ := r["run"].([]any) - if r["type"] != "process" || h["kind"] != want[0] || len(run) != 2 || run[1] != want[1] { - t.Errorf("%s: %v", id, r) - } + e := byID["events"] + if h, _ := e["health"].(map[string]any); h["kind"] != "unit" || e["user"] != nil { + t.Errorf("the follower runs as root, judged by its unit: %v", e) } - if h := byID["watch"]["health"].(map[string]any); h["tool"] != "zfs_health" { - t.Errorf("the watch is judged by zfs_health: %v", h) + if h, _ := byID["scrub-schedule"]["health"].(map[string]any); h["kind"] != "unit" { + t.Errorf("the scrub timer is judged by its unit: %v", byID["scrub-schedule"]) } if strings.Contains(raw, `"package"`) { t.Errorf("the module installs no package: ZFS is the machine's, and its kernel module is built against its kernel") } } -// No destroy, rollback, set, send or any other change but a snapshot. Every command the bundle runs goes -// through ask, AsRoot or Escalated with an argument list from one of the functions below, each of which is -// held to its verb here; a call site that builds its own list fails this test. A new verb needs a decision -// first, and then a line here. -func TestTheBundleRunsOnlyReadingVerbsAndSnapshot(t *testing.T) { - allowed := map[string]string{"DatasetsArgv": "list", "SnapshotsArgv": "list", "PoolsArgv": "list", "StatusArgv": "status", - "IOArgv": "iostat", "EventsArgv": "events", "HistoryArgv": "history", "PropertiesArgv": "get", "SnapshotArgv": "snapshot", "FollowArgv": "events"} - verbs := map[string][]string{"DatasetsArgv": DatasetsArgv(), "SnapshotsArgv": SnapshotsArgv(), "PoolsArgv": PoolsArgv(), - "StatusArgv": StatusArgv(), "IOArgv": IOArgv(3), "EventsArgv": EventsArgv(), "HistoryArgv": HistoryArgv("tank"), - "PropertiesArgv": PropertiesArgv("tank"), "SnapshotArgv": SnapshotArgv("tank", "x", true), "FollowArgv": FollowArgv()} - for fn, argv := range verbs { - if argv[0] != allowed[fn] { - t.Errorf("%s runs %q, not %q", fn, argv[0], allowed[fn]) +// One schedule per pool: the module's timer for the cadence the settings name is running and enabled, +// and the distribution's weekly and monthly timers for the same pool are stopped and disabled in the same +// declaration. The service runs zpool with fixed arguments and no shell. +func TestExactlyOneScrubScheduleAndItsCommandIsFixed(t *testing.T) { + m, _ := readManifest(t) + byID := map[string]map[string]any{} + for _, r := range m.Resources { + byID[r["id"].(string)] = r + } + mine := byID["scrub-schedule"] + if mine["unit"] != "zfs-mesh-scrub-${setting:scrub-cadence}@${setting:scrub-pool}.timer" || mine["state"] != "running" || mine["boot"] != "enabled" { + t.Errorf("the module's timer: %v", mine) + } + for _, c := range []string{"weekly", "monthly"} { + d := byID["distribution-"+c] + if d["unit"] != "zfs-scrub-"+c+"@${setting:scrub-pool}.timer" || d["state"] != "stopped" || d["boot"] != "disabled" { + t.Errorf("the distribution's %s timer: %v", c, d) + } + timer, _ := byID["scrub-"+c]["content"].(string) + if byID["scrub-"+c]["path"] != "/etc/systemd/system/zfs-mesh-scrub-"+c+"@.timer" || !strings.Contains(timer, "Unit=zfs-mesh-scrub@%i.service") || + !strings.Contains(timer, "Persistent=true") || !strings.Contains(timer, "OnCalendar=${setting:scrub-day} ") { + t.Errorf("the %s timer: %v", c, byID["scrub-"+c]) } } - call := regexp.MustCompile(`\.(ask|AsRoot|Escalated|Command|CommandContext)\(`) - site := regexp.MustCompile(`\.(?:ask|AsRoot|Escalated|CommandContext)\((?:\w+, )?"(zfs|zpool)", (\w+)\(`) + svc, _ := byID["scrub-service"]["content"].(string) + var execs []string + for _, l := range strings.Split(svc, "\n") { + if strings.HasPrefix(l, "Exec") { + execs = append(execs, l) + } + } + if strings.Join(execs, "|") != "ExecStart=/usr/bin/zpool scrub -w -- %i|ExecStop=-/usr/bin/zpool scrub -p -- %i" { + t.Errorf("the scrub service runs: %v", execs) + } + var settings struct { + Settings map[string]map[string]any `json:"settings"` + } + raw, _ := os.ReadFile("../../module.json") + json.Unmarshal(raw, &settings) + if settings.Settings["scrub-cadence"]["default"] != "weekly" || settings.Settings["scrub-day"]["default"] != "Mon" || + settings.Settings["scrub-time"]["default"] != "00:00" { + t.Errorf("defaults: %v", settings.Settings) + } + if _, has := settings.Settings["scrub-pool"]; has { + t.Errorf("the pool is the operator's value, with no default (ADR 0112, ADR 0262)") + } + conf, _ := byID["scrub-config"]["content"].(string) + if _, err := ParseScrubConfig(strings.NewReplacer("${setting:scrub-pool}", "storage", "${setting:scrub-cadence}", "weekly", + "${setting:scrub-day}", "Mon", "${setting:scrub-time}", "00:00").Replace(conf)); err != nil || byID["scrub-config"]["path"] != ScrubConfig { + t.Errorf("the configuration the tools read: %v", err) + } +} + +// Nothing but reading, a snapshot and a scrub's start, pause or stop. Every command the bundle runs goes +// through ask, AsRoot, Escalated, Run, exec.Command or exec.CommandContext with an argument list from one +// of the functions below, each held to its program and verb; a call site that builds its own list fails +// this test. A new verb needs a decision first, and then a line here. +func TestTheBundleRunsOnlyReadingVerbsSnapshotAndScrub(t *testing.T) { + allowed := map[string][2]string{ + "DatasetsArgv": {"zfs", "list"}, "SnapshotsArgv": {"zfs", "list"}, "PropertiesArgv": {"zfs", "get"}, + "SnapshotArgv": {"zfs", "snapshot"}, + "PoolsArgv": {"zpool", "list"}, "StatusArgv": {"zpool", "status"}, "IOArgv": {"zpool", "iostat"}, + "EventsArgv": {"zpool", "events"}, "HistoryArgv": {"zpool", "history"}, "FollowArgv": {"zpool", "events"}, + "ScrubArgv": {"zpool", "scrub"}, + "TimerShowArgv": {"systemctl", "show"}, "ServiceShowArgv": {"systemctl", "show"}, + } + verbs := map[string][]string{"DatasetsArgv": DatasetsArgv(), "SnapshotsArgv": SnapshotsArgv(), "PoolsArgv": PoolsArgv(), + "StatusArgv": StatusArgv(), "IOArgv": IOArgv(3), "EventsArgv": EventsArgv(), "HistoryArgv": HistoryArgv("tank"), + "PropertiesArgv": PropertiesArgv("tank"), "SnapshotArgv": SnapshotArgv("tank", "x"), "FollowArgv": FollowArgv(), + "TimerShowArgv": TimerShowArgv("x.timer"), "ServiceShowArgv": ServiceShowArgv("x.service")} + for fn, argv := range verbs { + if argv[0] != allowed[fn][1] { + t.Errorf("%s runs %q, not %q", fn, argv[0], allowed[fn][1]) + } + } + for _, act := range []string{"start", "pause", "stop", "anything"} { + argv := ScrubArgv(act, "tank") + if argv[0] != "scrub" || argv[len(argv)-2] != "--" || argv[len(argv)-1] != "tank" || len(argv) > 4 { + t.Errorf("%s: %v", act, argv) + } + if len(argv) == 4 && argv[1] != "-p" && argv[1] != "-s" { + t.Errorf("%s: %v", act, argv) + } + } + call := regexp.MustCompile(`(\.(ask|AsRoot|Escalated|Run|Start|Output|CombinedOutput)\(|exec\.Command(Context)?\(|os\.StartProcess\(|syscall\.(Exec|ForkExec)\()`) + site := regexp.MustCompile(`(?:\.(?:ask|AsRoot|Escalated)|exec\.Command)\((?:\w+, )?"(zfs|zpool|systemctl)", (\w+)\(`) + // The bodies that run what they are given, each once. + bodies := map[string]bool{ + "machine.go: r := m.Run(ctx, name, args...)": true, + "machine.go: r := m.Run(ctx, program, argv...)": true, + "machine.go: program, argv := m.Escalated(name, args...)": true, + "machine.go: cmd := exec.Command(name, args...)": true, + "machine.go: if err := cmd.Start(); err != nil {": true, + "follow.go: if err := cmd.Start(); err != nil {": true, + } files, _ := filepath.Glob("*.go") sites := 0 for _, file := range files { @@ -130,24 +205,25 @@ func TestTheBundleRunsOnlyReadingVerbsAndSnapshot(t *testing.T) { t.Fatal(err) } for i, l := range strings.Split(string(b), "\n") { - if !call.MatchString(l) || strings.HasPrefix(strings.TrimSpace(l), "func ") || strings.HasPrefix(strings.TrimSpace(l), "//") { + trimmed := strings.TrimSpace(l) + if !call.MatchString(l) || strings.HasPrefix(trimmed, "//") || bodies[file+":"+l] { continue } - if strings.Contains(l, "m.Escalated(name, args...)") || (file == "machine.go" && strings.Contains(l, "exec.CommandContext(ctx, name, args...)")) { - continue // AsRoot's and the runner's own bodies - } m := site.FindStringSubmatch(l) if m == nil { - t.Errorf("%s:%d runs a command not built by an argument function: %s", file, i+1, strings.TrimSpace(l)) + t.Errorf("%s:%d runs a command not built by an argument function: %s", file, i+1, trimmed) continue } - if _, ok := allowed[m[2]]; !ok { + want, ok := allowed[m[2]] + if !ok { t.Errorf("%s:%d runs %s's list, which is not held here", file, i+1, m[2]) + } else if want[0] != m[1] { + t.Errorf("%s:%d runs %s with %s's list", file, i+1, m[1], m[2]) } sites++ } } - if sites < 10 { + if sites < 14 { t.Errorf("found %d call sites; the test no longer sees them", sites) } } diff --git a/modules/zfs/cmd/zfs-tools/parse_test.go b/modules/zfs/cmd/zfs-tools/parse_test.go index 08f66c33..5d76e1a3 100644 --- a/modules/zfs/cmd/zfs-tools/parse_test.go +++ b/modules/zfs/cmd/zfs-tools/parse_test.go @@ -110,9 +110,9 @@ func TestStatusGivesEachPoolsLayoutWithSectionsAndTheLastScrub(t *testing.T) { if kids[3].Role != "spare" || kids[3].Children[0].State != "AVAIL" || kids[3].Children[0].Note != "" { t.Errorf("spares: %+v", kids[3].Children[0]) } - s := tank.Scan + s := tank.Scrub() end := time.Date(2026, 9, 14, 2, 34, 6, 0, time.Local) - if s.Kind != "scrub" || s.State != "finished" || s.Took != "1 days 02:10:05" || s.Repaired != "0" || deref(s.Errors) != 0 || + if s.Kind != "scrub" || s.State != "finished" || s.Took != "1 days 02:10:05" || s.Repaired != "0B" || deref(s.Errors) != 0 || s.Ended == nil || !s.Ended.Equal(end) || s.Started == nil || !s.Started.Equal(end.Add(-26*time.Hour-10*time.Minute-5*time.Second)) { t.Errorf("tank's scrub: %+v", s) } @@ -141,7 +141,7 @@ func TestADegradedPoolSaysItsFaultedDeviceItsErrorsAndTheResilver(t *testing.T) if in := p.Root.Children[1].Children[0]; in.State != "INUSE" || in.Note != "currently in use" { t.Errorf("the spare in use: %+v", in) } - s := p.Scan + s := p.Resilvers()[0] if s.Kind != "resilver" || s.State != "running" || s.Done == nil || *s.Done != 22.72 || s.ToGo != "08:25:13" || s.Started == nil || !s.Started.Equal(time.Date(2026, 10, 8, 21, 2, 17, 0, time.Local)) { t.Errorf("the resilver: %+v", s) @@ -153,16 +153,16 @@ func TestARunningScrubSaysItsProgress(t *testing.T) { if err != nil { t.Fatal(err) } - s := st[0].Scan - if s.Kind != "scrub" || s.State != "running" || *s.Done != 29.17 || s.ToGo != "06:49:34" || s.Repaired != "0" { + s := st[0].Scrub() + if s.Kind != "scrub" || s.State != "running" || *s.Done != 29.17 || s.ToGo != "06:49:34" || s.Repaired != "0B" { t.Errorf("scrub: %+v", s) } for _, said := range []string{"none requested", "scrub canceled on Sun Oct 4 01:00:00 2026", "scrub paused since Sun Oct 4 01:00:00 2026"} { - if got := parseScan(said); got.State == "unknown" { + if got := parseScan("scan", said); got.State == "unknown" { t.Errorf("%q not read: %+v", said, got) } } - if got := parseScan("resilvered 1088516226 in 03:22:11 with 0 errors on Fri Oct 9 06:00:00 2026"); got.Kind != "resilver" || got.State != "finished" || got.Repaired != "1088516226" { + if got := parseScan("scan", "resilvered 1.01G in 03:22:11 with 0 errors on Fri Oct 9 06:00:00 2026"); got.Kind != "resilver" || got.State != "finished" || got.Repaired != "1.01G" { t.Errorf("a finished resilver: %+v", got) } } @@ -183,8 +183,8 @@ func TestIOSampleNamesEachLinesPoolAndKindFromTheLayout(t *testing.T) { if err != nil { t.Fatal(err) } - want := map[string]string{"tank": "pool", "raidz2-0": "vdev", "ata-WDC_WD120EFBX-68B0EN0_D7JA0001": "device", "logs": "section", - "mirror-1": "vdev", "cache": "section", "rpool": "pool", "nvme-Samsung_SSD_970_EVO_Plus_500GB_S4EVNX0R200001-part2": "device"} + want := map[string]string{"tank": "pool", "raidz2-0": "vdev", "ata-WDC_WD120EFBX-68B0EN0_D7JA0001": "device", + "mirror-1": "vdev", "rpool": "pool", "nvme-Samsung_SSD_970_EVO_Plus_500GB_S4EVNX0R200001-part2": "device"} for _, r := range rows { if k, ok := want[r.Name]; ok && r.Kind != k { t.Errorf("%s is a %s, said %s", r.Name, k, r.Kind) @@ -362,7 +362,7 @@ func TestIOAndScrubAnswerFromFakes(t *testing.T) { if err != nil { t.Fatal(err) } - if a := got.(IOAnswer); len(a.Rows) != 12 || a.Seconds != 3 { + if a := got.(IOAnswer); len(a.Rows) != 10 || a.Seconds != 3 { t.Errorf("io: %+v", a) } if argv := IOArgv(3); strings.Join(argv, " ") != "iostat -y -Hpv 3 1" { @@ -375,9 +375,9 @@ func TestIOAndScrubAnswerFromFakes(t *testing.T) { a := got.(ScrubAnswer) rp, tank := a.Pools[0], a.Pools[1] if tank.DaysSince == nil || *tank.DaysSince != 25.4 || tank.Warning != "" { - t.Errorf("tank was scrubbed 25 days ago: %+v", tank) + t.Errorf("tank was scrubbed 25 days ago, and has no schedule here: %+v", tank) } - if rp.Warning == "" || !strings.Contains(rp.Said, "WARNING") { + if rp.Warning == "" || !strings.Contains(strings.Join(rp.Said, " "), "WARNING") { t.Errorf("rpool was scrubbed in July, more than 35 days ago: %+v", rp) } if len(ran(f, "sudo")) != 0 { @@ -397,7 +397,7 @@ func TestScrubWithHistoryReadsItAsRootAndFindsTheScrubStatusNoLongerShows(t *tes if r.LastScrub == nil || !r.LastScrub.Ended.Equal(time.Date(2026, 7, 13, 2, 30, 0, 0, time.Local)) || r.Warning == "" { t.Errorf("the last scrub, from the history, is 88 days old: %+v", r) } - if r.LastResilver == nil || r.Last.State != "running" { + if r.LastResilver == nil || r.Scans[0].State != "running" { t.Errorf("the resilver: %+v", r) } } diff --git a/modules/zfs/cmd/zfs-tools/pools.go b/modules/zfs/cmd/zfs-tools/pools.go index c9ceac6d..18d1cb8f 100644 --- a/modules/zfs/cmd/zfs-tools/pools.go +++ b/modules/zfs/cmd/zfs-tools/pools.go @@ -121,20 +121,29 @@ type Device struct { // counts what was found at the vdev, not the sum of its disks. func (d *Device) Errors() uint64 { return d.Read + d.Write + d.Checksum } -// Scan is a pool's last scan, as status says it: ZFS keeps only the latest, a scrub's or a resilver's. +// Scan is one `scan:` or `scrub:` line of status with its continuation. Status gives a pool's scrub +// (or, when it was more recent, its error scrub), and then its resilver: the pool-wide one, or the +// rebuild of each top-level vdev that had one (a sequential resilver, named by its vdev). ZFS keeps one +// pool-wide scan, so a resilver after a scrub hides that scrub; the pool's history still has it. type Scan struct { - // Kind is scrub or resilver; "" when none was ever asked. - Kind string `json:"kind,omitempty"` - // State is finished, running, paused, canceled or none. - State string `json:"state"` - Started *time.Time `json:"started,omitempty"` - Ended *time.Time `json:"ended,omitempty"` - Took string `json:"took,omitempty"` - Repaired string `json:"repaired,omitempty"` - Errors *int `json:"errors,omitempty"` - Done *float64 `json:"done_pct,omitempty"` - ToGo string `json:"to_go,omitempty"` - Said string `json:"said"` + // Kind is scrub, resilver or error scrub. + Kind string `json:"kind"` + // Vdev is the top-level vdev of a rebuild; "" for a pool-wide scan. + Vdev string `json:"vdev,omitempty"` + // State is finished, running, paused, canceled or unknown. + State string `json:"state"` + Started *time.Time `json:"started,omitempty"` + Paused *time.Time `json:"paused,omitempty"` + Ended *time.Time `json:"ended,omitempty"` + Took string `json:"took,omitempty"` + // Repaired is what a scrub repaired or a resilver rewrote, in status's own human size (status prints + // it so even under -p); for an error scrub, the error blocks it scrubbed. + Repaired string `json:"repaired,omitempty"` + Errors *int `json:"errors,omitempty"` + Done *float64 `json:"done_pct,omitempty"` + ToGo string `json:"to_go,omitempty"` + NoEstimate bool `json:"no_estimate,omitempty"` + Said string `json:"said"` } // PoolStatus is one pool as `zpool status` says it. @@ -144,7 +153,8 @@ type PoolStatus struct { Status string `json:"status,omitempty"` Action string `json:"action,omitempty"` See string `json:"see,omitempty"` - Scan Scan `json:"scan"` + // Scans are the scan lines status gives, in its order; none when no scan was ever asked. + Scans []Scan `json:"scans"` // Other are the lines status gives for a removal, a checkpoint or an expansion. Other map[string]string `json:"other,omitempty"` Root *Device `json:"layout,omitempty"` @@ -161,11 +171,16 @@ func ParseStatus(out string) ([]PoolStatus, error) { inConfig := false var stack []*Device section := "" + var scanKeys, scanSaid []string flush := func() { if cur != nil { - cur.Scan = parseScan(cur.Scan.Said) + cur.Scans = []Scan{} + for i := range scanSaid { + cur.Scans = append(cur.Scans, parseScan(scanKeys[i], scanSaid[i])) + } pools = append(pools, *cur) } + scanKeys, scanSaid = nil, nil } for _, raw := range strings.Split(out, "\n") { line := strings.TrimRight(raw, "\r ") @@ -193,8 +208,8 @@ func ParseStatus(out string) ([]PoolStatus, error) { cur.Action = v case "see": cur.See = v - case "scan": - cur.Scan.Said = v + case "scan", "scrub": + scanKeys, scanSaid = append(scanKeys, k), append(scanSaid, v) case "errors": cur.Errors = v case "pool", "config": @@ -217,8 +232,8 @@ func ParseStatus(out string) ([]PoolStatus, error) { add(&cur.Status) case "action": add(&cur.Action) - case "scan": - cur.Scan.Said += "\n" + trimmed + case "scan", "scrub": + scanSaid[len(scanSaid)-1] += "\n" + trimmed case "errors": add(&cur.Errors) default: @@ -345,51 +360,62 @@ func count(s string) uint64 { } var ( - scanFinished = regexp.MustCompile(`^(scrub repaired|resilvered) (\S+) in (.+?) with (\d+) errors on (.+)$`) - scanRunning = regexp.MustCompile(`^(scrub|resilver) in progress since (.+)$`) - scanPaused = regexp.MustCompile(`^(scrub|resilver) paused since (.+)$`) - scanCanceled = regexp.MustCompile(`^(scrub|resilver) canceled on (.+)$`) - scanDone = regexp.MustCompile(`([\d.]+)% done`) - scanToGo = regexp.MustCompile(`(\d+ days \d+:\d+:\d+|\d+:\d+:\d+) to go`) - scanRepaired = regexp.MustCompile(`(\S+) repaired`) + scrubFinished = regexp.MustCompile(`^scrub repaired (\S+) in (.+?) with (\d+) errors on (.+)$`) + resilverFinished = regexp.MustCompile(`^resilvered (?:\((\S+)\) )?(\S+) in (.+?) with (\d+) errors on (.+)$`) + scanRunning = regexp.MustCompile(`^(scrub|resilver|error scrub)(?: \((\S+)\))? in progress since (.+)$`) + scanPaused = regexp.MustCompile(`^(scrub|error scrub) paused since (.+)$`) + scanCanceled = regexp.MustCompile(`^(scrub|resilver|error scrub)(?: \((\S+)\))? canceled on (.+)$`) + errScrubFinished = regexp.MustCompile(`^scrubbed (\d+) error blocks in (\d+ days \d+:\d+:\d+) on (.+)$`) + scanStartedOn = regexp.MustCompile(`(?m)^(?:scrub|error scrub) started on (.+)$`) + scanDone = regexp.MustCompile(`([\d.]+)% done`) + scanToGo = regexp.MustCompile(`(\d+ days \d+:\d+:\d+|\d+:\d+:\d+) to go`) + scanRepaired = regexp.MustCompile(`(?m)^(\S+) (?:repaired|resilvered),`) ) -// parseScan reads status's scan line and its continuation. -func parseScan(said string) Scan { - s := Scan{State: "none", Said: said} +// parseScan reads one scan line and its continuation, as zpool_main.c's print_scan_scrub_resilver_status, +// print_rebuild_status_impl and print_err_scrub_status write them (OpenZFS 2.4.4). +func parseScan(key, said string) Scan { + s := Scan{State: "unknown", Said: said} first, more, _ := strings.Cut(said, "\n") first = strings.TrimSpace(first) switch { - case first == "" || first == "none requested": + case first == "none requested": + s.State = "none" return s - case scanFinished.MatchString(first): - m := scanFinished.FindStringSubmatch(first) - s.Kind, s.State, s.Repaired, s.Took = "scrub", "finished", m[2], m[3] - if m[1] == "resilvered" { - s.Kind = "resilver" - } - n, _ := strconv.Atoi(m[4]) - s.Errors = &n - s.Ended = when(m[5]) - if s.Ended != nil { - if d, ok := took(m[3]); ok { - st := s.Ended.Add(-d) - s.Started = &st - } - } + case scrubFinished.MatchString(first): + m := scrubFinished.FindStringSubmatch(first) + s.Kind, s.State, s.Repaired, s.Took = "scrub", "finished", m[1], m[2] + s.Errors, s.Ended = atoiPtr(m[3]), when(m[4]) + case resilverFinished.MatchString(first): + m := resilverFinished.FindStringSubmatch(first) + s.Kind, s.Vdev, s.State, s.Repaired, s.Took = "resilver", m[1], "finished", m[2], m[3] + s.Errors, s.Ended = atoiPtr(m[4]), when(m[5]) + case errScrubFinished.MatchString(first): + m := errScrubFinished.FindStringSubmatch(first) + s.Kind, s.State, s.Repaired, s.Took, s.Ended = "error scrub", "finished", m[1]+" error blocks", m[2], when(m[3]) case scanRunning.MatchString(first): m := scanRunning.FindStringSubmatch(first) - s.Kind, s.State, s.Started = m[1], "running", when(m[2]) + s.Kind, s.Vdev, s.State, s.Started = m[1], m[2], "running", when(m[3]) case scanPaused.MatchString(first): m := scanPaused.FindStringSubmatch(first) - s.Kind, s.State, s.Started = m[1], "paused", when(m[2]) + s.Kind, s.State, s.Paused = m[1], "paused", when(m[2]) case scanCanceled.MatchString(first): m := scanCanceled.FindStringSubmatch(first) - s.Kind, s.State, s.Ended = m[1], "canceled", when(m[2]) - default: - s.State = "unknown" + s.Kind, s.Vdev, s.State, s.Ended = m[1], m[2], "canceled", when(m[3]) + } + if s.Kind == "" && key == "scrub" { + s.Kind = "error scrub" + } + if s.State == "finished" && s.Ended != nil { + if d, ok := took(s.Took); ok { + st := s.Ended.Add(-d) + s.Started = &st + } } if more != "" { + if m := scanStartedOn.FindStringSubmatch(more); m != nil { + s.Started = when(m[1]) + } if m := scanDone.FindStringSubmatch(more); m != nil { v, _ := strconv.ParseFloat(m[1], 64) s.Done = &v @@ -397,6 +423,7 @@ func parseScan(said string) Scan { if m := scanToGo.FindStringSubmatch(more); m != nil { s.ToGo = m[1] } + s.NoEstimate = strings.Contains(more, "no estimated completion time") if m := scanRepaired.FindStringSubmatch(more); m != nil && s.Repaired == "" { s.Repaired = m[1] } @@ -404,6 +431,48 @@ func parseScan(said string) Scan { return s } +func atoiPtr(s string) *int { + n, err := strconv.Atoi(s) + if err != nil { + return nil + } + return &n +} + +// Scrub is the pool's scrub as status shows it; nil when status shows none (never asked, or hidden by a +// later resilver). +func (p PoolStatus) Scrub() *Scan { + for i := range p.Scans { + if p.Scans[i].Kind == "scrub" { + return &p.Scans[i] + } + } + return nil +} + +// Resilvers are the pool's resilvers as status shows them: the pool-wide one, or each vdev's rebuild. +func (p PoolStatus) Resilvers() []Scan { + var out []Scan + for _, s := range p.Scans { + if s.Kind == "resilver" { + out = append(out, s) + } + } + return out +} + +// ScansSaid is every scan line's first line, joined. +func (p PoolStatus) ScansSaid() string { + var out []string + for _, s := range p.Scans { + out = append(out, firstLine(s.Said)) + } + if len(out) == 0 { + return "no scan on record" + } + return strings.Join(out, "; ") +} + // when reads status's dates, as ctime writes them: "Sun Sep 13 05:36:34 2026", in local time. func when(s string) *time.Time { s = strings.TrimSpace(s) @@ -482,7 +551,7 @@ func (m *Machine) PoolsNow(ctx context.Context) (any, error) { for _, p := range ps { h := PoolHealth{PoolRow: p.Row(), State: p.Health} if s := statusOf(st, p.Name); s != nil { - h.State, h.Status, h.Action, h.Errors, h.Scan = s.State, s.Status, s.Action, s.Errors, firstLine(s.Scan.Said) + h.State, h.Status, h.Action, h.Errors, h.Scan = s.State, s.Status, s.Action, s.Errors, s.ScansSaid() h.DeviceErrs = sumErrors(s.Root) } line := h.Said + fmt.Sprintf("; %d device errors; errors: %s", h.DeviceErrs, h.Errors) diff --git a/modules/zfs/cmd/zfs-tools/review_test.go b/modules/zfs/cmd/zfs-tools/review_test.go new file mode 100644 index 00000000..46e0b8ff --- /dev/null +++ b/modules/zfs/cmd/zfs-tools/review_test.go @@ -0,0 +1,319 @@ +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) + } +} diff --git a/modules/zfs/cmd/zfs-tools/schedule.go b/modules/zfs/cmd/zfs-tools/schedule.go new file mode 100644 index 00000000..7dd0bb86 --- /dev/null +++ b/modules/zfs/cmd/zfs-tools/schedule.go @@ -0,0 +1,251 @@ +package main + +import ( + "context" + "fmt" + "regexp" + "strconv" + "strings" + "time" +) + +// The scrub schedule the module owns. +// +// The mesh writes ScrubConfig from the assignment's settings, and with it two timer templates of the +// module's own, weekly and monthly, and the service they start, which runs `zpool scrub -w ` with a +// fixed argument list. It enables the one timer the cadence names for the one pool the settings name, and +// holds the distribution's own scrub timers for that pool stopped and disabled, so exactly one schedule +// scrubs the pool. The tools read the configuration and ask the service manager what the timer and the +// service say; they never change either. + +// ScrubConfig is the schedule as the mesh wrote it from the settings. +const ScrubConfig = "/etc/zfs-tools/scrub.conf" + +// Margins after a cadence before a last scrub is said to be late: a weekly run that waited for a busy +// pool, a monthly run on the first given weekday of a month (28 or 35 days apart). +var cadenceAllows = map[string]time.Duration{ + "weekly": 9 * 24 * time.Hour, + "monthly": 38 * 24 * time.Hour, +} + +// Schedule is the pool's scrub schedule: what the settings say and what the service manager says of it. +type Schedule struct { + Pool string `json:"pool"` + Cadence string `json:"cadence"` + Day string `json:"day"` + Time string `json:"time"` + Timer string `json:"timer"` + Service string `json:"service"` + // TimerState and Enabled are the timer's ActiveState and UnitFileState. + TimerState string `json:"timer_state,omitempty"` + Enabled string `json:"enabled,omitempty"` + Next *time.Time `json:"next_run,omitempty"` + LastTrigger *time.Time `json:"last_triggered,omitempty"` + // LastResult is the service's Result of its last run (success, exit-code, …), LastExit when it ended. + LastResult string `json:"last_result,omitempty"` + ServiceState string `json:"service_state,omitempty"` + LastExit *time.Time `json:"last_run_ended,omitempty"` + Note string `json:"note,omitempty"` +} + +var ( + poolName = regexp.MustCompile(`^[A-Za-z][A-Za-z0-9_.:-]*$`) + weekday = regexp.MustCompile(`^(Mon|Tue|Wed|Thu|Fri|Sat|Sun)$`) + clock = regexp.MustCompile(`^([01][0-9]|2[0-3]):[0-5][0-9]$`) +) + +// ParseScrubConfig reads the schedule: pool, cadence (weekly or monthly), day (Mon … Sun) and time (HH:MM). +func ParseScrubConfig(text string) (*Schedule, error) { + v := map[string]string{} + for _, l := range strings.Split(text, "\n") { + l = strings.TrimSpace(l) + if l == "" || strings.HasPrefix(l, "#") { + continue + } + k, val, ok := strings.Cut(l, "=") + if !ok { + return nil, fmt.Errorf("%s: %q is not key=value", ScrubConfig, l) + } + v[strings.TrimSpace(k)] = strings.TrimSpace(val) + } + s := &Schedule{Pool: v["pool"], Cadence: v["cadence"], Day: v["day"], Time: v["time"]} + switch { + case !poolName.MatchString(s.Pool): + return nil, fmt.Errorf("the scrub-pool setting %q is not a pool's name", s.Pool) + case cadenceAllows[s.Cadence] == 0: + return nil, fmt.Errorf("the scrub-cadence setting is %q; it is weekly or monthly", s.Cadence) + case !weekday.MatchString(s.Day): + return nil, fmt.Errorf("the scrub-day setting is %q; it is Mon, Tue, Wed, Thu, Fri, Sat or Sun", s.Day) + case !clock.MatchString(s.Time): + return nil, fmt.Errorf("the scrub-time setting is %q; it is HH:MM, 00:00 to 23:59", s.Time) + } + s.Timer = "zfs-mesh-scrub-" + s.Cadence + "@" + s.Pool + ".timer" + s.Service = "zfs-mesh-scrub@" + s.Pool + ".service" + return s, nil +} + +// TimerShowArgv asks the service manager what a timer says: whether it runs and is enabled, when it +// fires next and when it last did, as Unix times. +func TimerShowArgv(unit string) []string { + return []string{"show", "--timestamp=unix", "--property=ActiveState,UnitFileState,NextElapseUSecRealtime,LastTriggerUSec", "--", unit} +} + +// ServiceShowArgv asks what the scrub service's last run was. +func ServiceShowArgv(unit string) []string { + return []string{"show", "--timestamp=unix", "--property=ActiveState,Result,ExecMainStartTimestamp,ExecMainExitTimestamp", "--", unit} +} + +// parseShow reads `systemctl show`'s key=value lines. +func parseShow(out string) map[string]string { + v := map[string]string{} + for _, l := range lines(out) { + if k, val, ok := strings.Cut(l, "="); ok { + v[k] = strings.TrimSpace(val) + } + } + return v +} + +// unixStamp reads `--timestamp=unix`: "@1791842400"; nil for "", "n/a" or 0. +func unixStamp(s string) *time.Time { + s = strings.TrimPrefix(strings.TrimSpace(s), "@") + n, err := strconv.ParseInt(s, 10, 64) + if err != nil || n == 0 { + return nil + } + t := time.Unix(n, 0) + return &t +} + +// ScheduleNow is the schedule with what the service manager says of it; nil when the module has no +// schedule on this machine (no configuration written). +func (m *Machine) ScheduleNow(ctx context.Context) (*Schedule, error) { + raw, err := m.ReadFile(ScrubConfig) + if err != nil { + return nil, nil + } + s, err := ParseScrubConfig(string(raw)) + if err != nil { + return nil, err + } + if out, err := m.ask(ctx, "systemctl", TimerShowArgv(s.Timer)...); err != nil { + s.Note = "the service manager did not say what the timer is: " + err.Error() + } else { + v := parseShow(out) + s.TimerState, s.Enabled = v["ActiveState"], v["UnitFileState"] + s.Next, s.LastTrigger = unixStamp(v["NextElapseUSecRealtime"]), unixStamp(v["LastTriggerUSec"]) + } + if out, err := m.ask(ctx, "systemctl", ServiceShowArgv(s.Service)...); err == nil { + v := parseShow(out) + s.ServiceState, s.LastResult, s.LastExit = v["ActiveState"], v["Result"], unixStamp(v["ExecMainExitTimestamp"]) + } + return s, nil +} + +// scheduleFindings are the schedule's warnings: a timer not waiting, a last run that failed with no scrub +// finished since. +func scheduleFindings(s *Schedule, scrubEnded *time.Time) []string { + var warn []string + if s.TimerState != "" && (s.TimerState != "active" || s.Enabled != "enabled") { + warn = append(warn, fmt.Sprintf("The scrub schedule's timer %s is %s and %s, so no scheduled scrub of %s will start.", + s.Timer, s.TimerState, s.Enabled, s.Pool)) + } + if s.LastResult != "" && s.LastResult != "success" && s.ServiceState != "activating" && + (scrubEnded == nil || s.LastExit == nil || scrubEnded.Before(*s.LastExit)) { + when := "at a time the service manager did not say" + if s.LastExit != nil { + when = s.LastExit.Local().Format("2006-01-02 15:04") + } + warn = append(warn, fmt.Sprintf("The last scheduled scrub of %s failed (%s), %s; its journal says why.", s.Pool, s.LastResult, when)) + } + return warn +} + +// ScrubEvent is the event each scrub act is published as (module.json's emits). +const ScrubEvent = "scrub.requested" + +// ScrubArgv is each act's command: fixed words, the pool after `--`. +func ScrubArgv(act, pool string) []string { + switch act { + case "pause": + return []string{"scrub", "-p", "--", pool} + case "stop": + return []string{"scrub", "-s", "--", pool} + } + return []string{"scrub", "--", pool} +} + +// ScrubActAnswer is what zfs_scrub_start, zfs_scrub_pause and zfs_scrub_stop answer. +type ScrubActAnswer struct { + Done bool `json:"done"` + Act string `json:"act"` + Pool string `json:"pool"` + Why string `json:"why"` + Ran []string `json:"ran"` + After string `json:"after"` + Recorded bool `json:"recorded"` + Record string `json:"record"` + Said string `json:"said"` +} + +// ScrubAct starts, pauses or stops a pool's scrub, and answers what status says afterwards. A scrub reads +// every block and rewrites from redundancy only a block it finds damaged; it adds I/O load, and never +// changes what a file holds. +func (m *Machine) ScrubAct(ctx context.Context, act, pool, why string) (ScrubActAnswer, error) { + a := ScrubActAnswer{Act: act, Pool: pool, Why: why} + switch act { + case "start", "pause", "stop": + default: + return a, fmt.Errorf("%q is not an act of the scrub: start, pause or stop", act) + } + switch { + case why == "": + return a, fmt.Errorf("say why: a scrub act is a person's, and the why is kept with it") + case strings.ContainsAny(why, "\n\r") || len(why) > MaxWhy: + return a, fmt.Errorf("say why in one line of at most %d characters", MaxWhy) + } + ps, err := m.Pools(ctx) + if err != nil { + return a, err + } + known := false + for _, p := range ps { + known = known || p.Name == pool + } + if !known { + return a, fmt.Errorf("there is no pool %q on this machine; zfs_pools lists them", pool) + } + program, argv := m.Escalated("zpool", ScrubArgv(act, pool)...) + a.Ran = append([]string{program}, argv...) + _, runErr := m.AsRoot(ctx, "zpool", ScrubArgv(act, pool)...) + _, timedOut := runErr.(errTimedOut) + if st, err := m.Status(ctx); err == nil { + if p := statusOf(st, pool); p != nil { + a.After = p.ScansSaid() + } + } + a.Done = runErr == nil + switch { + case timedOut: + a.Said = fmt.Sprintf("zpool scrub did not answer within its time and was ended: outcome unknown; check zfs_scrub. Status now: %s.", a.After) + case runErr != nil: + a.Said = fmt.Sprintf("NOT DONE: %v. Status now: %s.", runErr, a.After) + default: + a.Said = fmt.Sprintf("Asked %s to %s its scrub. Status now: %s. Why: %s.", pool, act, a.After, strings.TrimSuffix(why, ".")) + } + if m.Emit == nil { + a.Record = "this process publishes no events" + } else if err := m.Emit(ScrubEvent, map[string]any{"pool": pool, "act": act, "why": why, "done": a.Done, + "after": a.After, "at": m.Now().UTC().Format(time.RFC3339)}); err != nil { + a.Record = err.Error() + } else { + a.Recorded, a.Record = true, "published as the event "+ScrubEvent + } + if !a.Recorded { + a.Said += " NOT RECORDED on the bus: " + a.Record + "; the pool's own history (zpool history) has the command." + } + if runErr != nil { + return a, fmt.Errorf("%s", a.Said) + } + return a, nil +} diff --git a/modules/zfs/cmd/zfs-tools/scrub.go b/modules/zfs/cmd/zfs-tools/scrub.go index 7a41abf3..6d455b6d 100644 --- a/modules/zfs/cmd/zfs-tools/scrub.go +++ b/modules/zfs/cmd/zfs-tools/scrub.go @@ -89,35 +89,46 @@ func ParseHistory(out string) (scrub, resilver *Pass) { // ScrubRow is one pool's scans. type ScrubRow struct { Pool string `json:"pool"` - // Last is the pool's last scan as status says it: ZFS keeps only the latest, a scrub's or a resilver's. - Last Scan `json:"last_scan"` - // LastScrub and LastResilver are the last finished of each, from the history when it was read. + // Scans are the pool's scan lines as status gives them: its scrub or error scrub, then its resilver. + Scans []Scan `json:"scans"` + // LastScrub and LastResilver are the last finished of each, from status, or from the history when it + // was read and status no longer shows it. LastScrub *Pass `json:"last_scrub,omitempty"` LastResilver *Pass `json:"last_resilver,omitempty"` DaysSince *float64 `json:"days_since_last_scrub,omitempty"` Warning string `json:"warning,omitempty"` Note string `json:"note,omitempty"` - Said string `json:"said"` + Said []string `json:"said"` } // ScrubAnswer is what zfs_scrub answers. type ScrubAnswer struct { Applicable bool `json:"applicable"` Pools []ScrubRow `json:"pools"` + Schedule *Schedule `json:"schedule,omitempty"` Said []string `json:"said"` } -// LastScrubEnded is when the pool's last scrub finished, as status shows it; nil when status's last scan -// is not a finished scrub. -func LastScrubEnded(s Scan) *time.Time { - if s.Kind == "scrub" && s.State == "finished" { +// LastScrubEnded is when the pool's last scrub finished, as status shows it; nil when status shows no +// finished scrub. +func LastScrubEnded(p PoolStatus) *time.Time { + if s := p.Scrub(); s != nil && s.State == "finished" { return s.Ended } return nil } -// Scrubs are every pool's last scrub and resilver. With history, each pool's history is read too (as -// root), for the scan status no longer shows. +// ScrubLate is how long after its last finished scrub a pool is late: its schedule's cadence and margin, +// or ScrubWarnAfter where the module has no schedule for it. +func ScrubLate(pool string, s *Schedule) (time.Duration, string) { + if s != nil && s.Pool == pool { + return cadenceAllows[s.Cadence], "its " + s.Cadence + " schedule allows" + } + return ScrubWarnAfter, "the module's line for a pool without a schedule" +} + +// Scrubs are every pool's scans, its schedule and when it fires next. With history, each pool's history +// is read too (as root), for the scrub and the resilver status no longer shows. func (m *Machine) Scrubs(ctx context.Context, history bool) (any, error) { st, err := m.Status(ctx) if err != nil { @@ -125,14 +136,37 @@ func (m *Machine) Scrubs(ctx context.Context, history bool) (any, error) { } now := m.Now() a := ScrubAnswer{Applicable: true, Pools: []ScrubRow{}, Said: []string{}} - for _, p := range st { - r := ScrubRow{Pool: p.Name, Last: p.Scan} - ended := LastScrubEnded(p.Scan) - if p.Scan.Kind == "resilver" && p.Scan.State == "finished" && p.Scan.Ended != nil { - r.LastResilver = &Pass{Kind: "resilver", Started: p.Scan.Started, Ended: p.Scan.Ended, Outcome: "finished", Errors: p.Scan.Errors} + sched, serr := m.ScheduleNow(ctx) + switch { + case serr != nil: + a.Said = append(a.Said, "The scrub schedule's settings are not valid: "+serr.Error()+".") + case sched == nil: + a.Said = append(a.Said, "The module has no scrub schedule on this machine (no "+ScrubConfig+").") + default: + a.Schedule = sched + line := fmt.Sprintf("%s scrub of %s, %s at %s, by %s (%s, %s)", sched.Cadence, sched.Pool, sched.Day, sched.Time, + sched.Timer, orUnknown(sched.TimerState), orUnknown(sched.Enabled)) + if sched.Next != nil { + line += "; next scheduled scrub of " + sched.Pool + ": " + sched.Next.Local().Format("2006-01-02 15:04") } - if ended != nil { - r.LastScrub = &Pass{Kind: "scrub", Started: p.Scan.Started, Ended: ended, Outcome: "finished", Errors: p.Scan.Errors} + if sched.LastResult != "" { + line += "; last run: " + sched.LastResult + } + a.Said = append(a.Said, line) + if sched.Note != "" { + a.Said = append(a.Said, sched.Note) + } + } + for _, p := range st { + r := ScrubRow{Pool: p.Name, Scans: p.Scans, Said: []string{}} + if ended := LastScrubEnded(p); ended != nil { + sc := p.Scrub() + r.LastScrub = &Pass{Kind: "scrub", Started: sc.Started, Ended: ended, Outcome: "finished", Errors: sc.Errors} + } + for _, rs := range p.Resilvers() { + if rs.State == "finished" && rs.Ended != nil && (r.LastResilver == nil || rs.Ended.After(*r.LastResilver.Ended)) { + r.LastResilver = &Pass{Kind: "resilver", Started: rs.Started, Ended: rs.Ended, Outcome: "finished", Errors: rs.Errors} + } } if history { hctx, cancel := context.WithTimeout(ctx, HistoryTimeout) @@ -150,56 +184,85 @@ func (m *Machine) Scrubs(ctx context.Context, history bool) (any, error) { } } } else if r.LastScrub == nil { - r.Note = "status shows only the last scan, which is not a finished scrub; ask with history=true for the last scrub the pool's history records" + r.Note = "status shows no finished scrub of this pool; ask with history=true for the last one the pool's history records" } + late, by := ScrubLate(p.Name, sched) if r.LastScrub != nil && r.LastScrub.Ended != nil { d := round1(now.Sub(*r.LastScrub.Ended).Hours() / 24) r.DaysSince = &d - if now.Sub(*r.LastScrub.Ended) > ScrubWarnAfter { - r.Warning = fmt.Sprintf("the last scrub of %s finished %.0f days ago, more than %d", p.Name, d, int(ScrubWarnAfter.Hours()/24)) + if now.Sub(*r.LastScrub.Ended) > late { + r.Warning = fmt.Sprintf("the last scrub of %s finished %.0f days ago, more than %s (%d days)", p.Name, d, by, int(late.Hours()/24)) } } else if history { r.Warning = fmt.Sprintf("no finished scrub of %s is on record", p.Name) } - r.Said = scrubSaid(r) + for _, sc := range p.Scans { + r.Said = append(r.Said, p.Name+": "+scanSaid(sc)) + } + if len(p.Scans) == 0 { + r.Said = append(r.Said, p.Name+": no scan was ever asked") + } + if r.DaysSince != nil { + r.Said = append(r.Said, fmt.Sprintf("%s: last finished scrub %.1f days ago", p.Name, *r.DaysSince)) + } + if r.Warning != "" { + r.Said = append(r.Said, p.Name+": WARNING: "+r.Warning) + } + if r.Note != "" { + r.Said = append(r.Said, p.Name+": "+r.Note) + } a.Pools = append(a.Pools, r) - a.Said = append(a.Said, r.Said) + a.Said = append(a.Said, r.Said...) } return a, nil } -func scrubSaid(r ScrubRow) string { - s := r.Last - var line string +// scanSaid says one scan in a line: a running one with its progress and the time to go. +func scanSaid(s Scan) string { + what := s.Kind + if s.Vdev != "" { + what += " of " + s.Vdev + } switch s.State { - case "none": - line = fmt.Sprintf("%s: no scan was ever asked", r.Pool) case "running", "paused": - line = fmt.Sprintf("%s: a %s is %s", r.Pool, s.Kind, s.State) + line := fmt.Sprintf("a %s is %s", what, s.State) if s.Started != nil { - line += " since " + s.Started.Local().Format("2006-01-02 15:04") + line += " (started " + s.Started.Local().Format("2006-01-02 15:04") + ")" } if s.Done != nil { line += fmt.Sprintf(", %.2f %% done", *s.Done) } - if s.ToGo != "" { + switch { + case s.ToGo != "": line += ", " + s.ToGo + " to go" + case s.NoEstimate: + line += ", no estimate of the time to go yet" } + return line case "finished": - line = fmt.Sprintf("%s: the last scan was a %s, finished %s after %s, %s repaired, %d errors", r.Pool, s.Kind, - stamp(s.Ended), s.Took, s.Repaired, deref(s.Errors)) + line := fmt.Sprintf("the last %s finished %s after %s, %s", what, stamp(s.Ended), s.Took, s.Repaired) + if s.Kind == "scrub" { + line += " repaired" + } else if s.Kind == "resilver" { + line += " resilvered" + } + if s.Errors != nil { + line += fmt.Sprintf(", %d errors", *s.Errors) + } + return line case "canceled": - line = fmt.Sprintf("%s: the last %s was canceled %s", r.Pool, s.Kind, stamp(s.Ended)) - default: - line = fmt.Sprintf("%s: scan: %s", r.Pool, firstLine(s.Said)) + return fmt.Sprintf("the last %s was canceled %s", what, stamp(s.Ended)) + case "none": + return "no scan was ever asked" } - if r.DaysSince != nil { - line += fmt.Sprintf("; last finished scrub %.1f days ago", *r.DaysSince) + return "scan: " + firstLine(s.Said) +} + +func orUnknown(s string) string { + if s == "" { + return "not known" } - if r.Warning != "" { - line += " — WARNING: " + r.Warning - } - return line + return s } func stamp(t *time.Time) string { diff --git a/modules/zfs/cmd/zfs-tools/scrubschedule_test.go b/modules/zfs/cmd/zfs-tools/scrubschedule_test.go new file mode 100644 index 00000000..3d7bbce8 --- /dev/null +++ b/modules/zfs/cmd/zfs-tools/scrubschedule_test.go @@ -0,0 +1,119 @@ +package main + +import ( + "context" + "strings" + "testing" + "time" +) + +const scrubConf = "pool=tank\ncadence=weekly\nday=Mon\ntime=00:00\n" + +// scheduled is the healthy fixtures with the module's scrub schedule for tank, its timer waiting and its +// last run a success. +func scheduled(t *testing.T) *fake { + f := withZFS(t) + f.files[ScrubConfig] = scrubConf + f.on(line("systemctl", TimerShowArgv("zfs-mesh-scrub-weekly@tank.timer")), + "ActiveState=active\nUnitFileState=enabled\nNextElapseUSecRealtime=@1791842400\nLastTriggerUSec=@1791237600\n") + f.on(line("systemctl", ServiceShowArgv("zfs-mesh-scrub@tank.service")), + "ActiveState=inactive\nResult=success\nExecMainStartTimestamp=@1791237600\nExecMainExitTimestamp=@1791331200\n") + return f +} + +func TestTheScheduleIsTheConfigAndWhatTheTimerSays(t *testing.T) { + f := scheduled(t) + got, err := f.machine().Scrubs(context.Background(), false) + if err != nil { + t.Fatal(err) + } + a := got.(ScrubAnswer) + s := a.Schedule + if s == nil || s.Pool != "tank" || s.Cadence != "weekly" || s.Timer != "zfs-mesh-scrub-weekly@tank.timer" || s.TimerState != "active" || + s.Enabled != "enabled" || s.Next == nil || !s.Next.Equal(time.Unix(1791842400, 0)) || s.LastResult != "success" { + t.Fatalf("schedule: %+v", s) + } + if !strings.Contains(strings.Join(a.Said, "\n"), "next scheduled scrub of tank: "+time.Unix(1791842400, 0).Local().Format("2006-01-02 15:04")) { + t.Errorf("said: %v", a.Said) + } +} + +func TestAScheduleThatIsNotSetIsSaidAndAnInvalidOneRefused(t *testing.T) { + f := withZFS(t) + got, _ := f.machine().Scrubs(context.Background(), false) + if a := got.(ScrubAnswer); a.Schedule != nil || !strings.Contains(strings.Join(a.Said, " "), "no scrub schedule") { + t.Errorf("no config: %+v", a) + } + for _, conf := range []string{ + "pool=tank\ncadence=daily\nday=Mon\ntime=00:00\n", + "pool=tank\ncadence=weekly\nday=Monday\ntime=00:00\n", + "pool=tank\ncadence=weekly\nday=Mon\ntime=25:00\n", + "pool=tank x\ncadence=weekly\nday=Mon\ntime=00:00\n", + } { + if _, err := ParseScrubConfig(conf); err == nil { + t.Errorf("accepted %q", conf) + } + } +} + +func TestTheScheduleWarnsOfAnOldScrubAFailedRunAndAStoppedTimer(t *testing.T) { + f := scheduled(t) + h := f.machine().Health(context.Background()) + if !h.Healthy { + t.Fatalf("%+v", h) + } + w := strings.Join(h.Warnings, " ") + // tank's last scrub finished 2026-09-14, 25 days before the fake clock: past weekly plus its margin. + if !strings.Contains(w, "Pool tank was last scrubbed 25 days ago, more than its weekly schedule allows (9 days)") { + t.Errorf("warnings: %v", h.Warnings) + } + f.on(line("systemctl", ServiceShowArgv("zfs-mesh-scrub@tank.service")), + "ActiveState=failed\nResult=exit-code\nExecMainStartTimestamp=@1791237600\nExecMainExitTimestamp=@1791237601\n") + f.on(line("systemctl", TimerShowArgv("zfs-mesh-scrub-weekly@tank.timer")), + "ActiveState=inactive\nUnitFileState=disabled\nNextElapseUSecRealtime=\nLastTriggerUSec=@1791237600\n") + w = strings.Join(f.machine().Health(context.Background()).Warnings, " ") + for _, want := range []string{"The last scheduled scrub of tank failed (exit-code)", "The scrub schedule's timer zfs-mesh-scrub-weekly@tank.timer is inactive and disabled"} { + if !strings.Contains(w, want) { + t.Errorf("lacks %q: %s", want, w) + } + } +} + +func TestTheScrubActsAreFixedCommandsWithWhyReadBackAndRecorded(t *testing.T) { + for act, cmd := range map[string]string{ + "start": "sudo -n zpool scrub -- tank", + "pause": "sudo -n zpool scrub -p -- tank", + "stop": "sudo -n zpool scrub -s -- tank", + } { + f := withZFS(t) + f.on(cmd, "") + a, err := f.machine().ScrubAct(context.Background(), act, "tank", "the operator asked") + if err != nil { + t.Fatalf("%s: %v", act, err) + } + if strings.Join(a.Ran, " ") != cmd || a.After == "" || !a.Done { + t.Errorf("%s: %+v", act, a) + } + if len(f.emitted) != 1 || f.emitted[0]["_type"] != ScrubEvent || f.emitted[0]["act"] != act || f.emitted[0]["why"] != "the operator asked" { + t.Errorf("%s recorded: %+v", act, f.emitted) + } + } + f := withZFS(t) + for _, c := range []struct{ act, pool, why, says string }{ + {"start", "nope", "why", "no pool"}, + {"start", "tank", "", "say why"}, + {"start", "-s", "why", "no pool"}, + {"destroy", "tank", "why", "not an act"}, + } { + if _, err := f.machine().ScrubAct(context.Background(), c.act, c.pool, c.why); err == nil || !strings.Contains(err.Error(), c.says) { + t.Errorf("%+v: %v", c, err) + } + } + if n := len(ran(f, "sudo")); n != 0 { + t.Errorf("a refusal ran %v", f.calls) + } + f.answers["sudo -n zpool scrub -- tank"] = Ran{Code: -1, TimedOut: true} + if _, err := f.machine().ScrubAct(context.Background(), "start", "tank", "why"); err == nil || !strings.Contains(err.Error(), "outcome unknown; check zfs_scrub") { + t.Errorf("timed out: %v", err) + } +} diff --git a/modules/zfs/cmd/zfs-tools/snapshot.go b/modules/zfs/cmd/zfs-tools/snapshot.go index 0b57cf13..94d86e19 100644 --- a/modules/zfs/cmd/zfs-tools/snapshot.go +++ b/modules/zfs/cmd/zfs-tools/snapshot.go @@ -15,7 +15,11 @@ const SnapshotEvent = "snapshot.taken" // The one act of this module: a snapshot of one dataset, by a person, with why. It adds a snapshot and // changes nothing else: no destroy, rollback, set or send exists in this module (novox/hq ADR 0051, the -// operator's data). ZFS takes a snapshot atomically, and with -r every child's at the same instant. +// operator's data). It snapshots one dataset only, never its children (no -r in this version). +// +// **A snapshot keeps space.** From the moment it is taken it holds every block of the dataset that is +// deleted or overwritten afterwards, so that space is not freed until the snapshot is destroyed, which +// no tool of the mesh does. Every answer says so, with the dataset's free space and the pool's capacity. // snapName is what a snapshot's own name may hold: letters, digits, dot, underscore and hyphen. var snapName = regexp.MustCompile(`^[A-Za-z0-9._-]+$`) @@ -27,12 +31,8 @@ const MaxName = 255 const MaxWhy = 500 // SnapshotArgv is the command for one snapshot: fixed words, the dataset@name after `--`. -func SnapshotArgv(dataset, name string, recursive bool) []string { - argv := []string{"snapshot"} - if recursive { - argv = append(argv, "-r") - } - return append(argv, "--", dataset+"@"+name) +func SnapshotArgv(dataset, name string) []string { + return []string{"snapshot", "--", dataset + "@" + name} } // Made is one snapshot as `zfs list` shows it after the act. @@ -45,13 +45,21 @@ type Made struct { // SnapshotAnswer is what zfs_snapshot answers: what the list shows after the act, not what was run. type SnapshotAnswer struct { - Done bool `json:"done"` - Dataset string `json:"dataset"` - Name string `json:"snapshot"` - Recursive bool `json:"recursive"` - Why string `json:"why"` - Ran []string `json:"ran"` - Made []Made `json:"made"` + Done bool `json:"done"` + // Outcome is made, not made, or unknown (the command ran out of time and the list does not show it). + Outcome string `json:"outcome"` + Dataset string `json:"dataset"` + Name string `json:"snapshot"` + Why string `json:"why"` + Ran []string `json:"ran"` + Made []Made `json:"made"` + // Available is the dataset's free space and PoolCapacity its pool's capacity, as the list says them + // after the act. + Pool string `json:"pool"` + Available uint64 `json:"available_bytes"` + PoolCapacity int `json:"pool_capacity_pct"` + PoolFree uint64 `json:"pool_free_bytes"` + Holds string `json:"holds"` // Others are the snapshots that came or went on the machine during the act and were not this act's — // another schedule's, say. Empty when nothing else changed. Others []string `json:"others_changed"` @@ -61,10 +69,10 @@ type SnapshotAnswer struct { } // TakeSnapshot takes dataset@name. It refuses an unknown dataset, a name with anything but -// [A-Za-z0-9._-], an empty why, and a snapshot that already exists (for -r, on any child too). It -// answers what `zfs list` shows afterwards. -func (m *Machine) TakeSnapshot(ctx context.Context, dataset, name, why string, recursive bool) (SnapshotAnswer, error) { - a := SnapshotAnswer{Dataset: dataset, Name: name, Recursive: recursive, Why: why, Made: []Made{}, Others: []string{}} +// [A-Za-z0-9._-], an empty why, and a snapshot that already exists. It answers what `zfs list` shows +// afterwards. +func (m *Machine) TakeSnapshot(ctx context.Context, dataset, name, why string) (SnapshotAnswer, error) { + a := SnapshotAnswer{Dataset: dataset, Name: name, Why: why, Made: []Made{}, Others: []string{}, Pool: poolOf(dataset)} switch { case dataset == "": return a, fmt.Errorf("name the dataset; zfs_datasets lists them") @@ -95,13 +103,6 @@ func (m *Machine) TakeSnapshot(ctx context.Context, dataset, name, why string, r return a, err } covered := []string{dataset} - if recursive { - for _, d := range ds { - if strings.HasPrefix(d.Name, dataset+"/") { - covered = append(covered, d.Name) - } - } - } had := names(before) for _, d := range covered { if had[d+"@"+name] { @@ -109,9 +110,10 @@ func (m *Machine) TakeSnapshot(ctx context.Context, dataset, name, why string, r } } - program, argv := m.Escalated("zfs", SnapshotArgv(dataset, name, recursive)...) + program, argv := m.Escalated("zfs", SnapshotArgv(dataset, name)...) a.Ran = append([]string{program}, argv...) - _, runErr := m.AsRoot(ctx, "zfs", SnapshotArgv(dataset, name, recursive)...) + _, runErr := m.AsRoot(ctx, "zfs", SnapshotArgv(dataset, name)...) + _, timedOut := runErr.(errTimedOut) // What is there now, whatever the command said. after, listErr := m.Snapshots(ctx) @@ -138,25 +140,40 @@ func (m *Machine) TakeSnapshot(ctx context.Context, dataset, name, why string, r } sort.Strings(a.Others) } - a.Done = runErr == nil && listErr == nil && len(a.Made) == len(covered) + // A command that ran out of time may still have made it: the list is the answer. + a.Done = (runErr == nil || timedOut) && listErr == nil && len(a.Made) == len(covered) + a.Holds = fmt.Sprintf("%s@%s holds every block of %s deleted or overwritten from now on, so that space "+ + "is not freed until it is destroyed by hand; no tool of the mesh destroys a snapshot", dataset, name, dataset) + space := m.spaceAfter(ctx, &a) switch { - case runErr != nil && len(a.Made) == 0: + case timedOut && !a.Done: + a.Outcome = "unknown" + a.Said = fmt.Sprintf("zfs snapshot did not answer within its time and was ended, and the list does not show %s@%s: "+ + "outcome unknown; check zfs_snapshots.", dataset, name) + case runErr != nil && !timedOut && len(a.Made) == 0: + a.Outcome = "not made" a.Said = fmt.Sprintf("NOT DONE: %v. No snapshot %s@%s is on the machine.", runErr, dataset, name) - case runErr != nil: - a.Said = fmt.Sprintf("zfs snapshot failed (%v), and yet the list shows %s.", runErr, madeNames(a.Made)) + case runErr != nil && !timedOut: + a.Outcome = "unknown" + a.Said = fmt.Sprintf("zfs snapshot failed (%v), and yet the list shows %s: outcome unknown; check zfs_snapshots.", runErr, madeNames(a.Made)) case listErr != nil: - a.Said = fmt.Sprintf("zfs snapshot said it succeeded, and the snapshots could not be listed again to see it: %v.", listErr) + a.Outcome = "unknown" + a.Said = fmt.Sprintf("zfs snapshot said it succeeded, and the snapshots could not be listed again to see it (%v): "+ + "outcome unknown; check zfs_snapshots.", listErr) case len(a.Made) != len(covered): + a.Outcome = "not made" a.Said = fmt.Sprintf("zfs snapshot said it succeeded, and the list shows %d of the %d snapshots it should have made: %s.", len(a.Made), len(covered), madeNames(a.Made)) default: + a.Outcome = "made" a.Said = fmt.Sprintf("Made %s, created %s. Why: %s.", madeNames(a.Made), a.Made[0].Created, strings.TrimSuffix(why, ".")) if len(a.Others) == 0 { a.Said += " No other snapshot came or went meanwhile." } else { a.Said += fmt.Sprintf(" Meanwhile, not by this act: %s.", strings.Join(a.Others, ", ")) } + a.Said += " " + space + " " + a.Holds + "." } a.Recorded, a.Record = m.record(a) @@ -179,14 +196,38 @@ func (m *Machine) record(a SnapshotAnswer) (bool, string) { if len(a.Made) > 0 { created = a.Made[0].Created } - err := m.Emit(SnapshotEvent, map[string]any{"dataset": a.Dataset, "snapshot": a.Name, "recursive": a.Recursive, - "why": a.Why, "done": a.Done, "made": madeNames(a.Made), "created": created, "at": m.Now().UTC().Format(time.RFC3339)}) + err := m.Emit(SnapshotEvent, map[string]any{"dataset": a.Dataset, "snapshot": a.Name, + "why": a.Why, "done": a.Done, "outcome": a.Outcome, "made": madeNames(a.Made), "created": created, + "at": m.Now().UTC().Format(time.RFC3339)}) if err != nil { return false, err.Error() } return true, "published as the event " + SnapshotEvent } +// spaceAfter reads the dataset's free space and its pool's capacity after the act, and says them. +func (m *Machine) spaceAfter(ctx context.Context, a *SnapshotAnswer) string { + var parts []string + if ds, err := m.Datasets(ctx); err == nil { + if d := find(ds, a.Dataset); d != nil { + a.Available = d.Available + parts = append(parts, fmt.Sprintf("%s has %s free", a.Dataset, bytesSaid(d.Available))) + } + } + if ps, err := m.Pools(ctx); err == nil { + for _, p := range ps { + if p.Name == a.Pool { + a.PoolCapacity, a.PoolFree = p.Capacity, p.Free + parts = append(parts, fmt.Sprintf("pool %s %d %% full (%s free)", p.Name, p.Capacity, bytesSaid(p.Free))) + } + } + } + if len(parts) == 0 { + return "The free space could not be read after the act." + } + return "Now " + strings.Join(parts, ", ") + "." +} + func names(ss []Snapshot) map[string]bool { out := map[string]bool{} for _, s := range ss { diff --git a/modules/zfs/cmd/zfs-tools/snapshot_test.go b/modules/zfs/cmd/zfs-tools/snapshot_test.go index 645d5fe6..def2e34f 100644 --- a/modules/zfs/cmd/zfs-tools/snapshot_test.go +++ b/modules/zfs/cmd/zfs-tools/snapshot_test.go @@ -26,16 +26,12 @@ func snapshotting(f *fake, cmd string, added ...string) { func TestTheSnapshotCommandIsFixedWordsThroughSudoWithTheNameAfterDashDash(t *testing.T) { m := &Machine{UID: 1000} - p, argv := m.Escalated("zfs", SnapshotArgv("tank/media", "before-move", false)...) + p, argv := m.Escalated("zfs", SnapshotArgv("tank/media", "before-move")...) if got := p + " " + strings.Join(argv, " "); got != takeLine { t.Errorf("ran %q", got) } - p, argv = m.Escalated("zfs", SnapshotArgv("tank", "x", true)...) - if got := p + " " + strings.Join(argv, " "); got != "sudo -n zfs snapshot -r -- tank@x" { - t.Errorf("recursive: %q", got) - } root := &Machine{UID: 0} - if p, argv := root.Escalated("zfs", SnapshotArgv("tank", "x", false)...); p != "zfs" || argv[0] != "snapshot" { + if p, argv := root.Escalated("zfs", SnapshotArgv("tank", "x")...); p != "zfs" || argv[0] != "snapshot" { t.Errorf("as root, no sudo: %s %v", p, argv) } } @@ -43,7 +39,7 @@ func TestTheSnapshotCommandIsFixedWordsThroughSudoWithTheNameAfterDashDash(t *te func TestASnapshotIsAnsweredFromTheListAfterwardsAndRecorded(t *testing.T) { f := withZFS(t) snapshotting(f, takeLine, "tank/media@before-move\t1791400000\t0\t26938034880512") - a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "before moving the library", false) + a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "before moving the library") if err != nil { t.Fatal(err) } @@ -68,7 +64,7 @@ func TestASnapshotIsAnsweredFromTheListAfterwardsAndRecorded(t *testing.T) { func TestASnapshotTheListDoesNotShowIsNotAnsweredAsMade(t *testing.T) { f := withZFS(t) f.on(takeLine, "") // zfs exits 0, and the list does not change - a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why", false) + a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why") if err == nil || a.Done || !strings.Contains(err.Error(), "the list shows 0 of the 1") { t.Fatalf("err %v, answer %+v", err, a) } @@ -80,7 +76,7 @@ func TestASnapshotTheListDoesNotShowIsNotAnsweredAsMade(t *testing.T) { func TestARefusedSudoIsSaidAndRecorded(t *testing.T) { f := withZFS(t) f.answers[takeLine] = Ran{Code: 1, Err: "sudo: a password is required"} - _, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why", false) + _, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why") if err == nil || !strings.Contains(err.Error(), "NOT DONE") || !strings.Contains(err.Error(), "sudo refused the operator account") { t.Fatalf("err: %v", err) } @@ -93,7 +89,7 @@ func TestAnUnrecordedActSaysSoLoudly(t *testing.T) { f := withZFS(t) snapshotting(f, takeLine, "tank/media@before-move\t1791400000\t0\t1") f.emitErr = errors.New("the bus did not accept it") - a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why", false) + a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why") if err != nil { t.Fatal(err) } @@ -105,7 +101,7 @@ func TestAnUnrecordedActSaysSoLoudly(t *testing.T) { func TestAnotherSnapshotMeanwhileIsSaidNotHidden(t *testing.T) { f := withZFS(t) snapshotting(f, takeLine, "tank/media@before-move\t1791400000\t0\t1", "tank/downloads@auto-1200\t1791547201\t0\t1") - a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why", false) + a, err := f.machine().TakeSnapshot(context.Background(), "tank/media", "before-move", "why") if err != nil { t.Fatal(err) } @@ -133,7 +129,7 @@ func TestEveryRefusalRunsNoSnapshotCommand(t *testing.T) { } for _, c := range cases { f := withZFS(t) - _, err := f.machine().TakeSnapshot(context.Background(), c.dataset, c.name, c.why, false) + _, err := f.machine().TakeSnapshot(context.Background(), c.dataset, c.name, c.why) if c.says == "" { if len(ran(f, "sudo -n zfs snapshot -- tank/media@-r")) != 1 { t.Errorf("%q: the name follows -- and runs as a name: %v", c.name, f.calls) @@ -149,30 +145,6 @@ func TestEveryRefusalRunsNoSnapshotCommand(t *testing.T) { } } -func TestRecursiveIsRefusedWhenAChildHasTheNameAlready(t *testing.T) { - f := withZFS(t) - _, err := f.machine().TakeSnapshot(context.Background(), "tank", "weekly", "why", true) - if err == nil || !strings.Contains(err.Error(), "tank/downloads@weekly already exists") { - t.Fatalf("err: %v", err) - } - // Without recursive, only tank's own name counts. - f = withZFS(t) - snapshotting(f, "sudo -n zfs snapshot -- tank@weekly", "tank@weekly\t1791400000\t0\t1") - if a, err := f.machine().TakeSnapshot(context.Background(), "tank", "weekly", "why", false); err != nil || len(a.Made) != 1 { - t.Errorf("tank@weekly alone: %v %+v", err, a) - } -} - -func TestRecursiveAnswersEveryChildsSnapshot(t *testing.T) { - f := withZFS(t) - snapshotting(f, "sudo -n zfs snapshot -r -- tank@all", "tank@all\t1\t0\t1", "tank/media@all\t1\t0\t1", - "tank/downloads@all\t1\t0\t1", "tank/vm@all\t1\t0\t1") - a, err := f.machine().TakeSnapshot(context.Background(), "tank", "all", "why", true) - if err != nil || len(a.Made) != 4 || !a.Recursive { - t.Fatalf("%v %+v", err, a) - } -} - func TestAMachineWithoutZFSSaysTheModuleDoesNotApply(t *testing.T) { f := newFake(t) // every command: executable file not found m := f.machine() diff --git a/modules/zfs/cmd/zfs-tools/testdata/zpool-iostat.txt b/modules/zfs/cmd/zfs-tools/testdata/zpool-iostat.txt index 279b2982..4ed0f985 100644 --- a/modules/zfs/cmd/zfs-tools/testdata/zpool-iostat.txt +++ b/modules/zfs/cmd/zfs-tools/testdata/zpool-iostat.txt @@ -1,12 +1,12 @@ tank 28797591658086 19184805568512 212 14 221249536 1048576 raidz2-0 28797591658086 19184805568512 212 14 221249536 1048576 -ata-WDC_WD120EFBX-68B0EN0_D7JA0001 - - 35 2 36874922 174762 -ata-WDC_WD120EFBX-68B0EN0_D7JA0002 - - 36 2 36874922 174762 -logs - - - - - - +ata-WDC_WD120EFBX-68B0EN0_D7JA0001 0 0 35 2 36874922 174762 +ata-WDC_WD120EFBX-68B0EN0_D7JA0002 0 0 36 2 36874922 174762 + mirror-1 12582912 16093544448 0 0 0 0 -nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100001-part1 - - 0 0 0 0 -nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100002-part1 - - 0 0 0 0 -cache - - - - - - +nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100001-part1 0 0 0 0 0 0 +nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100002-part1 0 0 0 0 0 0 + nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100001-part2 480000000000 520000000000 40 1 5242880 131072 rpool 85899345920 412316860416 3 25 98304 1310720 nvme-Samsung_SSD_970_EVO_Plus_500GB_S4EVNX0R200001-part2 85899345920 412316860416 3 25 98304 1310720 diff --git a/modules/zfs/cmd/zfs-tools/testdata/zpool-status-degraded.txt b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-degraded.txt index 263fa63d..2a7e5544 100644 --- a/modules/zfs/cmd/zfs-tools/testdata/zpool-status-degraded.txt +++ b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-degraded.txt @@ -4,8 +4,8 @@ status: One or more devices is currently being resilvered. The pool will continue to function, possibly in a degraded state. action: Wait for the resilver to complete. scan: resilver in progress since Thu Oct 8 21:02:17 2026 - 9876543210123 / 28797591658086 scanned at 1101004800/s, 6543210987654 / 28797591658086 issued at 734003200/s - 1088516226 resilvered, 22.72% done, 08:25:13 to go + 8.98T / 26.2T scanned at 1.03G/s, 5.95T / 26.2T issued at 700M/s + 1.01G resilvered, 22.72% done, 08:25:13 to go config: NAME STATE READ WRITE CKSUM diff --git a/modules/zfs/cmd/zfs-tools/testdata/zpool-status-rebuild.txt b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-rebuild.txt new file mode 100644 index 00000000..387e34f0 --- /dev/null +++ b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-rebuild.txt @@ -0,0 +1,46 @@ + pool: fast + state: ONLINE + scrub: scrubbed 12 error blocks in 0 days 00:01:02 on Tue Oct 6 10:00:00 2026 + scan: resilvered (mirror-0) 1.20T in 03:22:11 with 0 errors on Wed Oct 7 04:00:00 2026 + scan: resilver (mirror-1) in progress since Fri Oct 9 09:00:00 2026 + 310G / 1.80T scanned at 160M/s, 300G / 1.80T issued at 155M/s + 300G resilvered, 16.84% done, 02:40:11 to go +config: + + NAME STATE READ WRITE CKSUM + fast ONLINE 0 0 0 + mirror-0 ONLINE 0 0 0 + nvme-WD_BLACK_SN850X_2000GB_A001 ONLINE 0 0 0 + nvme-WD_BLACK_SN850X_2000GB_A002 ONLINE 0 0 0 + mirror-1 ONLINE 0 0 0 + nvme-WD_BLACK_SN850X_2000GB_A003 ONLINE 0 0 0 + nvme-WD_BLACK_SN850X_2000GB_A004 ONLINE 0 0 0 (resilvering) + +errors: No known data errors + + pool: slow + state: ONLINE + scrub: error scrub paused since Thu Oct 8 12:00:00 2026 + error scrub started on Thu Oct 8 11:00:00 2026 + 42.00% done, issued I/O for 5 error blocks +config: + + NAME STATE READ WRITE CKSUM + slow ONLINE 0 0 0 + sda ONLINE 0 0 2 + +errors: No known data errors + + pool: paused + state: ONLINE + scan: scrub paused since Thu Oct 8 12:00:00 2026 + scrub started on Thu Oct 8 01:00:00 2026 + 1.00T / 2.00T scanned, 900G / 2.00T issued + 0B repaired, 43.95% done +config: + + NAME STATE READ WRITE CKSUM + paused ONLINE 0 0 0 + sdb ONLINE 0 0 0 + +errors: No known data errors diff --git a/modules/zfs/cmd/zfs-tools/testdata/zpool-status-scrubbing.txt b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-scrubbing.txt index d19c9f35..fe0c21a2 100644 --- a/modules/zfs/cmd/zfs-tools/testdata/zpool-status-scrubbing.txt +++ b/modules/zfs/cmd/zfs-tools/testdata/zpool-status-scrubbing.txt @@ -1,8 +1,8 @@ pool: tank state: ONLINE scan: scrub in progress since Sun Oct 4 00:24:01 2026 - 13523942719488 / 28797591658086 scanned at 1298300000/s, 8400000000000 / 28797591658086 issued at 830000000/s - 0 repaired, 29.17% done, 06:49:34 to go + 12.3T / 26.2T scanned at 1.21G/s, 7.64T / 26.2T issued at 792M/s + 0B repaired, 29.17% done, 06:49:34 to go config: NAME STATE READ WRITE CKSUM diff --git a/modules/zfs/cmd/zfs-tools/testdata/zpool-status.txt b/modules/zfs/cmd/zfs-tools/testdata/zpool-status.txt index ac21bf87..4d3e818d 100644 --- a/modules/zfs/cmd/zfs-tools/testdata/zpool-status.txt +++ b/modules/zfs/cmd/zfs-tools/testdata/zpool-status.txt @@ -5,7 +5,7 @@ status: Some supported and requested features are not enabled on the pool. action: Enable all features using 'zpool upgrade'. Once this is done, the pool may no longer be accessible by software that does not support the features. See zpool-features(7) for details. - scan: scrub repaired 0 in 00:04:11 with 0 errors on Sun Jul 12 00:28:12 2026 + scan: scrub repaired 0B in 00:04:11 with 0 errors on Sun Jul 12 00:28:12 2026 config: NAME STATE READ WRITE CKSUM @@ -16,7 +16,7 @@ errors: No known data errors pool: tank state: ONLINE - scan: scrub repaired 0 in 1 days 02:10:05 with 0 errors on Mon Sep 14 02:34:06 2026 + scan: scrub repaired 0B in 1 days 02:10:05 with 0 errors on Mon Sep 14 02:34:06 2026 config: NAME STATE READ WRITE CKSUM @@ -26,11 +26,11 @@ config: ata-WDC_WD120EFBX-68B0EN0_D7JA0002 ONLINE 0 0 0 ata-WDC_WD120EFBX-68B0EN0_D7JA0003 ONLINE 0 0 0 ata-WDC_WD120EFBX-68B0EN0_D7JA0004 ONLINE 0 0 0 - logs + logs mirror-1 ONLINE 0 0 0 nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100001-part1 ONLINE 0 0 0 nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100002-part1 ONLINE 0 0 0 - cache + cache nvme-Samsung_SSD_980_PRO_1TB_S5P2NG0R100001-part2 ONLINE 0 0 0 spares ata-WDC_WD120EFBX-68B0EN0_D7JA0009 AVAIL diff --git a/modules/zfs/cmd/zfs-tools/tools.go b/modules/zfs/cmd/zfs-tools/tools.go index 80a9e57f..483b78a5 100644 --- a/modules/zfs/cmd/zfs-tools/tools.go +++ b/modules/zfs/cmd/zfs-tools/tools.go @@ -37,23 +37,22 @@ func Tools(m *Machine) []stdio.Tool { Name: "zfs_snapshot", Description: "Take a snapshot dataset@name of one dataset, a person's act with why: refused for a dataset that is not " + "on this machine, a name with anything but letters, digits, '.', '_' and '-', a snapshot that already exists, " + - "or no why. Only that dataset unless recursive is true, which snapshots every child at the same instant too. " + - "Runs zfs snapshot -- dataset@name through sudo -n, then answers what zfs list shows: the snapshot made " + - "and its creation time, and any other snapshot that came or went meanwhile. Recorded as the event " + - "snapshot.taken; ZFS keeps it in the pool's history too. It adds a snapshot and changes nothing else. " + - "Replaces zfs snapshot. (a)", + "or no why. Only that dataset, never its children. Runs zfs snapshot -- dataset@name through sudo -n, then " + + "answers what zfs list shows: the snapshot made, its creation time, any other snapshot that came or went " + + "meanwhile, the dataset's free space and the pool's capacity. From then on the snapshot holds every block " + + "of the dataset deleted or overwritten, until it is destroyed by hand. A command that ran out of time is " + + "answered from the list, or as outcome unknown. Recorded as the event snapshot.taken; ZFS keeps it in the " + + "pool's history too. It adds a snapshot and changes nothing else. Replaces zfs snapshot. (a)", Input: map[string]any{ - "dataset": dataset("the dataset, as zfs_datasets names it"), - "name": map[string]any{"type": "string", "description": "the snapshot's name, after the @: letters, digits, '.', '_' and '-'"}, - "why": map[string]any{"type": "string", "description": "why, in one line; kept with the act"}, - "recursive": map[string]any{"type": "boolean", "description": "true to snapshot every child dataset too (default false)"}, + "dataset": dataset("the dataset, as zfs_datasets names it"), + "name": map[string]any{"type": "string", "description": "the snapshot's name, after the @: letters, digits, '.', '_' and '-'"}, + "why": map[string]any{"type": "string", "description": "why, in one line; kept with the act"}, }, Run: func(a map[string]any) (any, error) { - recursive, err := flag(a, "recursive") - if err != nil { - return nil, err + if _, given := a["recursive"]; given { + return nil, fmt.Errorf("recursive does not exist in this version: zfs_snapshot snapshots one dataset, never its children") } - ans, err := m.TakeSnapshot(ctx, text(a, "dataset"), text(a, "name"), text(a, "why"), recursive) + ans, err := m.TakeSnapshot(ctx, text(a, "dataset"), text(a, "name"), text(a, "why")) if err != nil { if _, absentHere := err.(errAbsent); absentHere { return NotApplicable{Applicable: false, Said: err.Error()}, nil @@ -89,12 +88,13 @@ func Tools(m *Machine) []stdio.Tool { }, { Name: "zfs_scrub", - Description: "Each pool's last scan, as status says it (ZFS keeps only the latest, a scrub's or a resilver's): when it " + - "started and ended, how long it took, what it repaired and the errors it found, or, while one runs, its " + - "progress and the time to go; and how many days since the last finished scrub, with a WARNING past 35. " + - "With history true, also each pool's history (zpool history -i, as root through sudo -n) for the last " + - "finished scrub and resilver status no longer shows; it can take some seconds on a pool with a long life. " + - "Replaces zpool history -i. (r)", + Description: "Each pool's scans as status gives them: its scrub (or error scrub) and its resilver, the pool-wide one or " + + "each vdev's rebuild; when each started and ended, how long it took, what it repaired and the errors it " + + "found, or, while one runs, its progress and the time to go; and how many days since the last finished " + + "scrub, with a WARNING past what the schedule allows. Then the module's scrub schedule: the pool, the " + + "cadence, the day and time, its timer's state and the next run, and how the last run ended. With history " + + "true, also each pool's history (zpool history -i, as root through sudo -n) for the last finished scrub and " + + "resilver status no longer shows. Replaces zpool history -i. (r)", Input: map[string]any{"history": map[string]any{"type": "boolean", "description": "true to read each pool's history too (default false)"}}, Run: func(a map[string]any) (any, error) { h, err := flag(a, "history") @@ -104,6 +104,15 @@ func Tools(m *Machine) []stdio.Tool { return m.Scrubs(ctx, h) }, }, + scrubAct("start", "Start a scrub of one pool, or resume a paused one: zpool scrub -- pool through sudo -n, a person's "+ + "act with why. A scrub reads every block and rewrites from redundancy only a block it finds damaged; it adds "+ + "I/O load for its whole length (hours to days on a large pool) and never changes what a file holds. "+ + "Answers what status says afterwards; recorded as the event scrub.requested. Replaces zpool scrub. (a)", m), + scrubAct("pause", "Pause one pool's running scrub, keeping its place: zpool scrub -p -- pool through sudo -n, with why; "+ + "zfs_scrub_start resumes it. Answers what status says afterwards; recorded as the event scrub.requested. "+ + "Replaces zpool scrub -p. (a)", m), + scrubAct("stop", "Stop one pool's scrub, losing its place: zpool scrub -s -- pool through sudo -n, with why. Answers "+ + "what status says afterwards; recorded as the event scrub.requested. Replaces zpool scrub -s. (a)", m), { Name: "zfs_io", Description: "A sample of every pool's I/O over a few seconds (zpool iostat -v, the report since boot left out): " + @@ -159,16 +168,41 @@ func Tools(m *Machine) []stdio.Tool { }, { Name: "zfs_health", - Description: "Whether this machine's ZFS is healthy, as the module's health check (novox/hq ADR 0240): unhealthy " + - "when a pool is not ONLINE (with status's reason and action), a device has read, write or checksum " + - "errors or is not online, a pool reports data errors, a pool is more than 90 % full, no pool is " + - "imported, or ZFS is not on this machine; a pool more than 80 % full and a last scrub more than 35 " + - "days ago are warnings, which leave it healthy. With why, one sentence per finding. (r)", + Description: "Whether this machine's ZFS is healthy, as the module's health check (novox/hq ADR 0240). Unhealthy " + + "for a fault now: a pool not ONLINE (with status's reason and action), a device not online, a device's " + + "error counts that rose since the last look (unhealthy for 15 minutes after the rise), data errors, a " + + "resilver that finished with errors, a pool more than 90 % full, no pool imported, or ZFS not on this " + + "machine. Warnings leave it healthy: error counts from before, to clear by hand once understood; a pool " + + "more than 80 % full; a resilver running; a last scrub later than its schedule allows (or 35 days without " + + "one); a scheduled scrub that failed, or a schedule whose timer does not run. With why, one sentence per " + + "finding. (r)", Run: func(map[string]any) (any, error) { return m.Health(ctx), nil }, }, } } +// scrubAct is one of the scrub's acts as a tool. +func scrubAct(act, description string, m *Machine) stdio.Tool { + return stdio.Tool{ + Name: "zfs_scrub_" + act, + Description: description, + Input: map[string]any{ + "pool": map[string]any{"type": "string", "description": "the pool, as zfs_pools names it"}, + "why": map[string]any{"type": "string", "description": "why, in one line; kept with the act"}, + }, + Run: func(a map[string]any) (any, error) { + ans, err := m.ScrubAct(context.Background(), act, text(a, "pool"), text(a, "why")) + if err != nil { + if _, absentHere := err.(errAbsent); absentHere { + return NotApplicable{Applicable: false, Said: err.Error()}, nil + } + return nil, err + } + return ans, nil + }, + } +} + func text(a map[string]any, key string) string { s, _ := a[key].(string) return strings.TrimSpace(s) diff --git a/modules/zfs/cmd/zfs-tools/watch.go b/modules/zfs/cmd/zfs-tools/watch.go index a6bedbb1..92304f5d 100644 --- a/modules/zfs/cmd/zfs-tools/watch.go +++ b/modules/zfs/cmd/zfs-tools/watch.go @@ -37,8 +37,8 @@ func (w *Watch) Look(ctx context.Context) { } } -// Run looks every WatchEvery until the context ends. -func (w *Watch) Run(ctx context.Context) { +// Loop looks every WatchEvery until the context ends. +func (w *Watch) Loop(ctx context.Context) { w.Look(ctx) t := time.NewTicker(WatchEvery) defer t.Stop() diff --git a/modules/zfs/module.json b/modules/zfs/module.json index 9c3279c8..fc66eb6f 100644 --- a/modules/zfs/module.json +++ b/modules/zfs/module.json @@ -5,8 +5,26 @@ "service-manager" ], "emits": [ - "snapshot.taken" + "snapshot.taken", + "scrub.requested" ], + "settings": { + "scrub-cadence": { + "kind": "preference", + "default": "weekly", + "why": "how often the pool named by scrub-pool is scrubbed, weekly or monthly: weekly is what the distribution's timer did on the home server before the module, so taking it over changes nothing; a pool whose scrub takes days may want monthly" + }, + "scrub-day": { + "kind": "preference", + "default": "Mon", + "why": "the weekday the scrub starts (Mon to Sun); for a monthly scrub, the first such day of the month. Monday is when the distribution's weekly timer fired" + }, + "scrub-time": { + "kind": "preference", + "default": "00:00", + "why": "the time the scrub starts, HH:MM in the machine's time zone; midnight is when the distribution's weekly timer fired" + } + }, "tools": [ "zfs_datasets", "zfs_snapshots", @@ -15,6 +33,9 @@ "zfs_space", "zfs_pool_layout", "zfs_scrub", + "zfs_scrub_start", + "zfs_scrub_pause", + "zfs_scrub_stop", "zfs_io", "zfs_arc", "zfs_events", @@ -62,6 +83,15 @@ "zfs_properties": [ "zfs get all", "zfs get" + ], + "zfs_scrub_start": [ + "zpool scrub" + ], + "zfs_scrub_pause": [ + "zpool scrub -p" + ], + "zfs_scrub_stop": [ + "zpool scrub -s" ] }, "resources": [ @@ -74,6 +104,7 @@ "./zfs-tools", "watch" ], + "user": "${machine:account}", "health": { "kind": "tool", "tool": "zfs_health", @@ -83,6 +114,12 @@ "grace": "60s" } }, + { + "id": "cursor-dir", + "type": "directory", + "path": "/run/zfs-events", + "mode": "0700" + }, { "id": "events", "type": "process", @@ -95,6 +132,69 @@ "health": { "kind": "unit" } + }, + { + "id": "config-dir", + "type": "directory", + "path": "/etc/zfs-tools", + "mode": "0755" + }, + { + "id": "scrub-config", + "type": "file", + "path": "/etc/zfs-tools/scrub.conf", + "mode": "0644", + "content": "# Written by the mesh (module zfs) from this machine's assignment. Replaced on every push; change the\n# settings scrub-pool, scrub-cadence, scrub-day and scrub-time, never this file. The module's tools read it.\npool=${setting:scrub-pool}\ncadence=${setting:scrub-cadence}\nday=${setting:scrub-day}\ntime=${setting:scrub-time}\n" + }, + { + "id": "scrub-service", + "type": "file", + "path": "/etc/systemd/system/zfs-mesh-scrub@.service", + "mode": "0644", + "content": "# Written by the mesh (module zfs). Replaced on every push; change the module's scrub settings, never this file.\n# The scrub of one pool, started by the module's timer: zpool with fixed arguments and no shell. Stopping the\n# unit while a scrub runs pauses it, as the distribution's own scrub unit does; a later start resumes it.\n[Unit]\nDescription=zpool scrub of %i (the mesh's zfs module)\nDocumentation=man:zpool-scrub(8)\nRequires=zfs.target\nAfter=zfs.target\nConditionPathIsDirectory=/sys/module/zfs\n\n[Service]\nExecStart=/usr/bin/zpool scrub -w -- %i\nExecStop=-/usr/bin/zpool scrub -p -- %i\n" + }, + { + "id": "scrub-weekly", + "type": "file", + "path": "/etc/systemd/system/zfs-mesh-scrub-weekly@.timer", + "mode": "0644", + "content": "# Written by the mesh (module zfs). Replaced on every push; change the module's scrub settings, never this file.\n# The weekly scrub schedule. The mesh enables it for the pool its scrub-pool setting names, and holds the\n# distribution's own scrub timers for that pool stopped and disabled, so one schedule scrubs the pool.\n[Unit]\nDescription=Weekly zpool scrub of %i (the mesh's zfs module)\nDocumentation=man:zpool-scrub(8)\n\n[Timer]\nOnCalendar=${setting:scrub-day} *-*-* ${setting:scrub-time}:00\nPersistent=true\nUnit=zfs-mesh-scrub@%i.service\n\n[Install]\nWantedBy=timers.target\n" + }, + { + "id": "scrub-monthly", + "type": "file", + "path": "/etc/systemd/system/zfs-mesh-scrub-monthly@.timer", + "mode": "0644", + "content": "# Written by the mesh (module zfs). Replaced on every push; change the module's scrub settings, never this file.\n# The monthly scrub schedule. The mesh enables it for the pool its scrub-pool setting names, and holds the\n# distribution's own scrub timers for that pool stopped and disabled, so one schedule scrubs the pool.\n[Unit]\nDescription=Monthly zpool scrub of %i (the mesh's zfs module)\nDocumentation=man:zpool-scrub(8)\n\n[Timer]\nOnCalendar=${setting:scrub-day} *-*-01..07 ${setting:scrub-time}:00\nPersistent=true\nUnit=zfs-mesh-scrub@%i.service\n\n[Install]\nWantedBy=timers.target\n" + }, + { + "id": "distribution-weekly", + "type": "service", + "unit": "zfs-scrub-weekly@${setting:scrub-pool}.timer", + "state": "stopped", + "boot": "disabled" + }, + { + "id": "distribution-monthly", + "type": "service", + "unit": "zfs-scrub-monthly@${setting:scrub-pool}.timer", + "state": "stopped", + "boot": "disabled" + }, + { + "id": "scrub-schedule", + "type": "service", + "unit": "zfs-mesh-scrub-${setting:scrub-cadence}@${setting:scrub-pool}.timer", + "state": "running", + "boot": "enabled", + "restart-on": [ + "scrub-service", + "scrub-weekly", + "scrub-monthly" + ], + "health": { + "kind": "unit" + } } ], "build": {