issue 1841/S6: check after every upgrade the files it left, the news since the last one, units newly failed and a restart needed, so the operator sees what an upgrade asks of them

2026-10-22 14:37:58 +02:00
parent ac4d156cb7
commit 900a2da3e3
7 changed files with 300 additions and 10 deletions
@@ -0,0 +1,150 @@
+package main
+
+// The after-upgrade check (novox/hq ADR 0508 §4), written to the run as its last step: the .pacnew and .pacsave
+// files the transaction left, the distribution's news since the node's previous upgrade, the units failed now
+// that were not failed in the record, and whether a restart is needed (the running kernel is no longer the one
+// its package installed). It passes when the transaction succeeded and no unit newly failed (and, with the
+// second part, every DKMS module is built); the rest is said and does not stop the round. The mesh restarts no
+// machine (ADR 0477 §5).
+
+import (
+	"sort"
+	"strings"
+	"time"
+)
+
+// AfterCheck is the after-upgrade check of a run whose transaction ended, against the record taken before it
+// (nil when there is none: every unit failed now is then said as newly failed).
+func (u *Upgrades) AfterCheck(run Run, rec *Record) Check {
+	c := Check{Pacnew: []string{}, Pacsave: []string{}, News: []NewsTitle{}, Mapped: []Mapped{}, NewlyFailed: []string{}, Unbuilt: []DKMSBuild{}}
+	succeeded := transactionSucceeded(run)
+	var started time.Time
+	for _, s := range run.Steps {
+		if s.Step == StepStarted {
+			started = s.At
+		}
+	}
+	if !started.IsZero() {
+		if b := u.transactionBlock(run.Kind, started); b != nil {
+			c.Pacnew = append(c.Pacnew, b.Pacnew...)
+			c.Pacsave = append(c.Pacsave, b.Pacsave...)
+		}
+	}
+	c.News, c.NewsError = u.newsSince(u.previousUpgrade(run))
+	healthy := true
+	if failed, err := u.Machine.FailedUnits(); err != nil {
+		healthy = false
+		c.NewlyFailed = append(c.NewlyFailed, "(the failed units could not be read: "+err.Error()+")")
+	} else {
+		before := map[string]bool{}
+		if rec != nil {
+			for _, f := range rec.FailedUnits {
+				before[f] = true
+			}
+		}
+		for _, f := range failed {
+			if !before[f] {
+				c.NewlyFailed = append(c.NewlyFailed, f)
+			}
+		}
+	}
+	c.RunningKernel, c.InstalledKernel, c.RestartNeeded = u.restartNeeded()
+	c.Passed = succeeded && healthy && len(c.NewlyFailed) == 0
+	return c
+}
+
+// previousUpgrade is when the node's upgrade before this run started: its previous run with a transaction.
+func (u *Upgrades) previousUpgrade(run Run) time.Time {
+	runs, err := u.ownRuns()
+	if err != nil {
+		return time.Time{}
+	}
+	var last time.Time
+	for _, r := range runs {
+		if r.Run.Run >= run.Run || r.Kind != RunUpgrade {
+			continue
+		}
+		for _, s := range r.Steps {
+			if s.Step == StepStarted && s.At.After(last) {
+				last = s.At
+			}
+		}
+	}
+	return last
+}
+
+// newsSince is the distribution's news published after a time, titles only; or why it could not be read.
+func (u *Upgrades) newsSince(since time.Time) ([]NewsTitle, string) {
+	body, err := fetch(NewsFeed)
+	if err != nil {
+		return []NewsTitle{}, err.Error()
+	}
+	items, err := ParseNews(body, since)
+	if err != nil {
+		return []NewsTitle{}, "the feed could not be read: " + err.Error()
+	}
+	titles := []NewsTitle{}
+	for _, it := range items {
+		titles = append(titles, NewsTitle{Title: it.Title, Link: it.Link, Published: it.Published})
+	}
+	return titles, ""
+}
+
+// kernelTag is a release's flavour, its letters alone: `7.2.8-arch1-2` is arch, `6.18.54-2-lts` is lts.
+func kernelTag(release string) string {
+	return strings.Map(func(r rune) rune {
+		if r >= 'a' && r <= 'z' {
+			return r
+		}
+		return -1
+	}, release)
+}
+
+// installedKernels are the releases the installed kernel packages install, sorted.
+func (m *Machine) installedKernels() ([]string, error) {
+	out, err := m.Out("pacman", "-Qq")
+	if err != nil {
+		return nil, err
+	}
+	var releases []string
+	for _, name := range lines(out) {
+		name = strings.TrimSpace(name)
+		if name != "linux" && !strings.HasPrefix(name, "linux-") {
+			continue
+		}
+		release, kernel, err := m.kernelRelease(name)
+		if err != nil {
+			return nil, err
+		}
+		if kernel {
+			releases = append(releases, release)
+		}
+	}
+	sort.Strings(releases)
+	return releases, nil
+}
+
+// restartNeeded compares the running kernel with what its package installs now: when no installed kernel is the
+// running one, the one of its flavour is what a restart would boot.
+func (u *Upgrades) restartNeeded() (running, installed string, needed bool) {
+	raw, err := u.Machine.ReadFile(OSRelease)
+	if err != nil {
+		return "(the running kernel could not be read: " + err.Error() + ")", "", false
+	}
+	running = strings.TrimSpace(string(raw))
+	kernels, err := u.Machine.installedKernels()
+	if err != nil {
+		return running, "(the installed kernels could not be read: " + err.Error() + ")", false
+	}
+	for _, k := range kernels {
+		if k == running {
+			return running, k, false
+		}
+	}
+	for _, k := range kernels {
+		if kernelTag(k) == kernelTag(running) {
+			return running, k, true
+		}
+	}
+	return running, "", true
+}
@@ -0,0 +1,120 @@
+package main
+
+// The after-upgrade check, its first part (novox/hq ADR 0508 §4; acceptance 1841/AC5): .pacnew and .pacsave
+// files from the transaction's log lines, the news since the previous upgrade, units newly failed against the
+// record, and a restart needed.
+
+import (
+	"errors"
+	"strings"
+	"testing"
+	"time"
+)
+
+const checkLog = "[2026-10-04T12:00:01+0000] [PACMAN] Running 'pacman -Syu --noconfirm'\n" +
+	"[2026-10-04T12:00:02+0000] [PACMAN] starting full system upgrade\n" +
+	"[2026-10-04T12:00:09+0000] [ALPM] transaction started\n" +
+	"[2026-10-04T12:00:10+0000] [ALPM] upgraded pacman-mirrorlist (20260901-1 -> 20261001-1)\n" +
+	"[2026-10-04T12:00:10+0000] [ALPM] warning: /etc/pacman.d/mirrorlist installed as /etc/pacman.d/mirrorlist.pacnew\n" +
+	"[2026-10-04T12:00:10+0000] [ALPM] warning: /etc/lemurs/config.toml saved as /etc/lemurs/config.toml.pacsave\n" +
+	"[2026-10-04T12:00:10+0000] [ALPM] removed lemurs-git (0.4.0.r17.g7151336-2)\n" +
+	"[2026-10-04T12:00:11+0000] [ALPM] transaction completed\n" +
+	"[2026-10-04T12:05:00+0000] [PACMAN] Running 'pacman -S --noconfirm made-up'\n" +
+	"[2026-10-04T12:05:01+0000] [ALPM] transaction started\n" +
+	"[2026-10-04T12:05:01+0000] [ALPM] warning: /etc/made-up.conf installed as /etc/made-up.conf.pacnew\n" +
+	"[2026-10-04T12:05:02+0000] [ALPM] transaction completed\n"
+
+const newsFeed = `<?xml version="1.0"?><rss><channel>
+<item><title>A manual intervention</title><link>https://example.org/news/2</link><pubDate>Fri, 02 Oct 2026 10:00:00 +0000</pubDate><description>x</description></item>
+<item><title>An older post</title><link>https://example.org/news/1</link><pubDate>Mon, 21 Sep 2026 10:00:00 +0000</pubDate><description>y</description></item>
+</channel></rss>`
+
+// checkMachine is a machine after an upgrade: these units failed now, this kernel running, and the linux
+// package now installing linuxNow.
+func checkMachine(failed, linuxNow string) *Machine {
+	m := machine(byLine(map[string]Ran{
+		"systemctl list-units --state=failed --plain --no-legend --no-pager": {Stdout: failed},
+		"pacman -Qq":                    {Stdout: "bash\nlinux\nlinux-firmware\nlinux-lts\n"},
+		"pacman -Qlq -- linux":          {Stdout: "/usr/lib/modules/" + linuxNow + "/vmlinuz\n"},
+		"pacman -Qlq -- linux-firmware": {Stdout: "/usr/lib/firmware/\n"},
+		"pacman -Qlq -- linux-lts":      {Stdout: "/usr/lib/modules/6.18.54-2-lts/vmlinuz\n"},
+	}, nil), 1000)
+	m.ReadFile = func(path string) ([]byte, error) {
+		switch path {
+		case OSRelease:
+			return []byte("7.2.8-arch1-2\n"), nil
+		case PacmanLog:
+			return []byte(checkLog), nil
+		}
+		return nil, errNoFile
+	}
+	return m
+}
+
+func checkedRun(steps ...string) Run {
+	r := Run{Node: "node-a", Run: "20261004T120000Z", Kind: RunUpgrade, From: FromAsk}
+	at := time.Date(2026, 10, 4, 12, 0, 0, 0, time.UTC)
+	for _, s := range steps {
+		r.Steps = append(r.Steps, Step{Step: s, At: at})
+	}
+	return r
+}
+
+func checkUpgrades(t *testing.T, m *Machine) *Upgrades {
+	runs := newBucket()
+	previous := Run{Node: "node-a", Run: "20260926T040000Z", Kind: RunUpgrade, From: FromRound,
+		Steps: []Step{{Step: StepStarted, At: time.Date(2026, 9, 26, 4, 0, 0, 0, time.UTC)}}}
+	if _, err := runs.Create(NodeKey("node-a", previous.Run), previous); err != nil {
+		t.Fatal(err)
+	}
+	saved := fetch
+	fetch = func(string) ([]byte, error) { return []byte(newsFeed), nil }
+	t.Cleanup(func() { fetch = saved })
+	return &Upgrades{Node: "node-a", Machine: m, Runs: runs}
+}
+
+func TestTheCheckNamesTheFilesTheTransactionLeftAndTheNewsSinceThePreviousUpgrade(t *testing.T) {
+	u := checkUpgrades(t, checkMachine("", "7.2.8-arch1-2"))
+	c := u.AfterCheck(checkedRun(StepStarted, StepFinished), &Record{})
+	if strings.Join(c.Pacnew, " ") != "/etc/pacman.d/mirrorlist.pacnew" || strings.Join(c.Pacsave, " ") != "/etc/lemurs/config.toml.pacsave" {
+		t.Errorf("only this transaction's files: %v %v", c.Pacnew, c.Pacsave)
+	}
+	if len(c.News) != 1 || c.News[0].Title != "A manual intervention" || c.NewsError != "" {
+		t.Errorf("the news since the previous upgrade (26 September): %+v %q", c.News, c.NewsError)
+	}
+	if !c.Passed || c.RestartNeeded || c.RunningKernel != "7.2.8-arch1-2" || c.InstalledKernel != "7.2.8-arch1-2" {
+		t.Errorf("%+v", c)
+	}
+}
+
+func TestNewsThatCannotBeReadIsSaidNotShownAsNone(t *testing.T) {
+	u := checkUpgrades(t, checkMachine("", "7.2.8-arch1-2"))
+	fetch = func(string) ([]byte, error) { return nil, errors.New("no route to host") }
+	c := u.AfterCheck(checkedRun(StepStarted, StepFinished), &Record{})
+	if !strings.Contains(c.NewsError, "no route to host") || !c.Passed {
+		t.Errorf("%+v", c)
+	}
+}
+
+func TestAUnitNewlyFailedFailsTheCheckAndOneFailedBeforeDoesNot(t *testing.T) {
+	u := checkUpgrades(t, checkMachine("backup.service loaded failed failed The backup\nweb.service loaded failed failed The web\n", "7.2.8-arch1-2"))
+	c := u.AfterCheck(checkedRun(StepStarted, StepFinished), &Record{FailedUnits: []string{"backup.service"}})
+	if strings.Join(c.NewlyFailed, " ") != "web.service" || c.Passed {
+		t.Errorf("%+v", c)
+	}
+}
+
+func TestARestartIsNeededWhenTheRunningKernelIsNoLongerTheInstalledOne(t *testing.T) {
+	u := checkUpgrades(t, checkMachine("", "7.2.9-arch1-1"))
+	c := u.AfterCheck(checkedRun(StepStarted, StepFinished), &Record{})
+	if !c.RestartNeeded || c.InstalledKernel != "7.2.9-arch1-1" || !c.Passed {
+		t.Errorf("a restart is said and does not fail the check: %+v", c)
+	}
+}
+
+func TestTheCheckPassesOnlyWhenTheTransactionSucceeded(t *testing.T) {
+	u := checkUpgrades(t, checkMachine("", "7.2.8-arch1-2"))
+	if c := u.AfterCheck(checkedRun(StepStarted, StepFailed), &Record{}); c.Passed {
+		t.Errorf("%+v", c)
+	}
+}
@@ -26,7 +26,7 @@ var busFields = map[string][]string{
 	"Step":             {"step", "at", "why", "held", "unit", "ignored", "plan", "exit", "error", "changes", "check"},
 	"HeldKernel":       {"package", "version", "module", "bound"},
 	"Changes":          {"added", "removed", "changed"},
-	"Check": {"passed", "pacnew", "pacsave", "news", "mapped", "newly_failed", "restart_needed", "running_kernel",
+	"Check": {"passed", "pacnew", "pacsave", "news", "news_error", "mapped", "newly_failed", "restart_needed", "running_kernel",
 		"installed_kernel", "unbuilt"},
 	"NewsTitle":        {"title", "link", "published"},
 	"Mapped":           {"unit", "container", "executable"},
@@ -231,6 +231,8 @@ type Check struct {
 	Pacsave []string `json:"pacsave"`
 	// The distribution's news since the node's previous upgrade.
 	News []NewsTitle `json:"news"`
+	// Why the news could not be read, when it could not: no news is then not said to be none.
+	NewsError string `json:"news_error,omitempty"`
 	// The units and containers whose processes still map a file the upgrade replaced.
 	Mapped []Mapped `json:"mapped"`
 	// The units failed now that were not failed in the record.
@@ -205,12 +205,11 @@ func (u *Upgrades) checkAfter(r *openRun) error {
 			rec = &got
 		}
 	}
-	var c Check
-	if u.Check != nil {
-		c = u.Check(r.Run, rec)
-	} else {
-		c = Check{Passed: transactionSucceeded(r.Run)}
+	check := u.Check
+	if check == nil {
+		check = u.AfterCheck
 	}
+	c := check(r.Run, rec)
 	if err := u.step(r, Step{Step: StepCheckedAfter, At: u.Machine.Now().UTC(), Check: &c}); err != nil {
 		return err
 	}
@@ -247,9 +246,9 @@ func (u *Upgrades) unitEnd(unit string) (done bool, exit int, err error) {
 	return true, exit, nil
 }

-// transactionChanges is what the run's transaction changed, read from its lines in pacman's log: the first
-// command of its kind pacman logged since the transaction was started.
-func (u *Upgrades) transactionChanges(kind string, since time.Time) *Changes {
+// transactionBlock is the run's transaction as pacman's log tells it: the first command of its kind pacman
+// logged since the transaction was started; nil when the log holds none.
+func (u *Upgrades) transactionBlock(kind string, since time.Time) *logBlock {
 	text, err := u.Machine.ReadFile(PacmanLog)
 	if err != nil {
 		return nil
@@ -262,6 +261,14 @@ func (u *Upgrades) transactionChanges(kind string, since time.Time) *Changes {
 		if kind == RunUpgrade && !b.Full || kind == RunRollback && !strings.Contains(b.Command, " -U") {
 			continue
 		}
+		return &b
+	}
+	return nil
+}
+
+// transactionChanges is what the run's transaction changed, read from its lines in pacman's log.
+func (u *Upgrades) transactionChanges(kind string, since time.Time) *Changes {
+	if b := u.transactionBlock(kind, since); b != nil {
 		c := b.Changes
 		return &c
 	}
@@ -53,6 +53,9 @@ const upgradeLog = "[2026-10-04T12:00:01+0000] [PACMAN] Running 'pacman -Syu --n
 func newKeeperBed(t *testing.T) *keeperBed {
 	k := &keeperBed{root: &fakeRoot{}, events: &eventLog{}, installed: newBucket(), updates: newBucket(), runs: newBucket(),
 		records: newBucket(), asks: newBucket(), now: time.Date(2026, 10, 4, 12, 0, 0, 0, time.UTC), unitState: "LoadState=not-found\n"}
+	saved := fetch
+	fetch = func(string) ([]byte, error) { return nil, errors.New("offline") }
+	t.Cleanup(func() { fetch = saved })
 	if _, err := k.installed.Put("node-a", nodeAPackages); err != nil {
 		t.Fatal(err)
 	}
@@ -57,7 +57,7 @@ type Upgrades struct {
 	Events  EventSink
 	// The module's states.
 	Installed, Updates, Runs, Records, Asks Bucket
-	// Check is the after-upgrade check (ADR 0508 §4); nil checks only that the transaction succeeded.
+	// Check is the after-upgrade check (ADR 0508 §4); nil is AfterCheck.
 	Check func(run Run, record *Record) Check
 }

@@ -101,6 +101,8 @@ func (u *Upgrades) emit(event string, body any) error {
 var (
 	runningLine     = regexp.MustCompile(`^\[([^\]]+)\] \[PACMAN\] Running '(.*)'$`)
 	transactionLine = regexp.MustCompile(`^\[([^\]]+)\] \[ALPM\] transaction (started|completed|failed|interrupted)$`)
+	pacnewLine      = regexp.MustCompile(`^\[[^\]]+\] \[ALPM\] warning: \S+ installed as (\S+\.pacnew)$`)
+	pacsaveLine     = regexp.MustCompile(`^\[[^\]]+\] \[ALPM\] warning: \S+ saved as (\S+\.pacsave)$`)
 )

 // logBlock is one command pacman ran, as its log tells it.
@@ -113,6 +115,8 @@ type logBlock struct {
 	End     string    // completed, failed or interrupted; empty when the log holds no end
 	EndAt   time.Time
 	Changes Changes
+	// The .pacnew and .pacsave files the transaction left, by path, in the order logged.
+	Pacnew, Pacsave []string
 }

 // logBlocks reads pacman's log into the commands it ran, oldest first.
@@ -157,6 +161,10 @@ func logBlocks(text string) []logBlock {
 		if cur.Began && cur.End == "" {
 			if m := logLine.FindStringSubmatch(l); m != nil {
 				addChange(&cur.Changes, m[2], m[3], m[4])
+			} else if m := pacnewLine.FindStringSubmatch(l); m != nil {
+				cur.Pacnew = append(cur.Pacnew, m[1])
+			} else if m := pacsaveLine.FindStringSubmatch(l); m != nil {
+				cur.Pacsave = append(cur.Pacsave, m[1])
 			}
 		}
 	}