diff --git a/modules/pacman/README.md b/modules/pacman/README.md index ae53b6b8..4ba4969a 100644 --- a/modules/pacman/README.md +++ b/modules/pacman/README.md @@ -33,9 +33,13 @@ that seat (ADR 0207). - **The outcome is the module's health.** The timer's resource asks `pacman_upgrade_health`: unhealthy, naming the exit and the last `error:` line of the journal, when the last weekly upgrade failed; healthy while it runs, after it passed, and before it ever ran. The controller raises the module's condition for - the node from it. A failed service stays failed until the next run, so the condition stands until an - upgrade passes, a hand `pacman_upgrade` does not clear it. A restart of the machine forgets the failed - state (the service manager's), so it is the condition raised before it that keeps the record. + the node from it. A failed service stays failed until + the next run, so the condition stands until an upgrade passes; a hand `pacman_upgrade` does not clear + it. A restart of the machine clears the failed state and with it the condition, and the next Saturday + runs again. A run that goes on longer than two hours is unhealthy too, naming when it started and the + last line of its journal: it is hung and holds pacman's database lock. The service has no start + timeout on purpose, because killing pacman in the middle of a transaction is worse; the hung run is + said, not killed. ## What it improves diff --git a/modules/pacman/cmd/pacman-tools/pacman_test.go b/modules/pacman/cmd/pacman-tools/pacman_test.go index c17b9d48..4ca7f5bb 100644 --- a/modules/pacman/cmd/pacman-tools/pacman_test.go +++ b/modules/pacman/cmd/pacman-tools/pacman_test.go @@ -378,8 +378,9 @@ func TestConfigIsReadAsPacmanConfResolvesIt(t *testing.T) { // The weekly upgrade's outcome is the module's health (issue 1574, ADR 0477 clause 5). func upgradeHealthMachine(props, journal string) *Machine { return machine(byLine(map[string]Ran{ - "systemctl show " + WeeklyUnit + " --no-pager --property=LoadState --property=ActiveState --property=Result --property=ExecMainStatus --property=ExecMainExitTimestamp": {Stdout: props}, + "systemctl show " + WeeklyUnit + " --no-pager --property=LoadState --property=ActiveState --property=Result --property=ExecMainStatus --property=ExecMainExitTimestamp --property=ExecMainStartTimestamp": {Stdout: props}, "sudo -n journalctl --no-pager -o cat -n 40 -u " + WeeklyUnit: {Stdout: journal}, + "sudo -n journalctl --no-pager -o cat -n 1 -u " + WeeklyUnit: {Stdout: journal}, }, nil), 1000) } @@ -398,7 +399,7 @@ func TestAFailedWeeklyUpgradeIsUnhealthyNamingTheError(t *testing.T) { func TestAPassedRunningOrNeverRunWeeklyUpgradeIsHealthy(t *testing.T) { for name, props := range map[string]string{ "passed": "LoadState=loaded\nActiveState=inactive\nResult=success\nExecMainStatus=0\nExecMainExitTimestamp=Sat 2026-10-24 04:09:00 CEST\n", - "running": "LoadState=loaded\nActiveState=activating\nResult=success\nExecMainStatus=0\nExecMainExitTimestamp=\n", + "running": "LoadState=loaded\nActiveState=activating\nResult=success\nExecMainStatus=0\nExecMainExitTimestamp=\nExecMainStartTimestamp=Wed 2026-10-04 11:50:00 UTC\n", "never run": "LoadState=loaded\nActiveState=inactive\nResult=success\nExecMainStatus=0\nExecMainExitTimestamp=\n", } { if h := upgradeHealthMachine(props, "").UpgradeHealth(); !h.Healthy { @@ -409,3 +410,21 @@ func TestAPassedRunningOrNeverRunWeeklyUpgradeIsHealthy(t *testing.T) { t.Errorf("a unit that cannot be read is not healthy: %+v", h) } } + +// A run that goes on past RunLimit is hung and holds pacman's lock: unhealthy, naming its start (issue 1574). +func TestAHungWeeklyUpgradeIsUnhealthyNamingItsStart(t *testing.T) { + // the test machine's clock is 2026-10-04 12:00 UTC + h := upgradeHealthMachine("LoadState=loaded\nActiveState=activating\nResult=success\nExecMainStatus=0\nExecMainStartTimestamp=Wed 2026-10-04 09:00:00 UTC\n", + "downloading linux-6.99...\n").UpgradeHealth() + if h.Healthy || !strings.Contains(h.Why, "Wed 2026-10-04 09:00:00 UTC") || !strings.Contains(h.Why, "downloading linux-6.99") { + t.Fatalf("started 3 h ago: %+v", h) + } + h = upgradeHealthMachine("LoadState=loaded\nActiveState=activating\nResult=success\nExecMainStatus=0\nExecMainStartTimestamp=Wed 2026-10-04 11:50:00 UTC\n", "").UpgradeHealth() + if !h.Healthy { + t.Fatalf("started 10 min ago: %+v", h) + } + h = upgradeHealthMachine("LoadState=loaded\nActiveState=activating\nResult=success\nExecMainStatus=0\nExecMainStartTimestamp=\n", "").UpgradeHealth() + if h.Healthy { + t.Fatalf("a start that cannot be read is not healthy: %+v", h) + } +} diff --git a/modules/pacman/cmd/pacman-tools/upgrade_health.go b/modules/pacman/cmd/pacman-tools/upgrade_health.go index 2b817bcf..90180130 100644 --- a/modules/pacman/cmd/pacman-tools/upgrade_health.go +++ b/modules/pacman/cmd/pacman-tools/upgrade_health.go @@ -3,6 +3,7 @@ package main import ( "fmt" "strings" + "time" ) // The weekly upgrade's outcome (issue 1574, ADR 0477 clause 5). The mesh runs a full upgrade on every node @@ -22,11 +23,20 @@ type Health struct { // WeeklyUnit is the service the weekly timer starts. const WeeklyUnit = "mesh-pacman-weekly-upgrade.service" +// RunLimit is how long a weekly upgrade may go on before it is unhealthy. The service has no start timeout on +// purpose: killing pacman in the middle of a transaction leaves a half-upgraded machine. A run past the limit +// is a hung one (a stuck hook, a stalled transaction), which holds pacman's database lock so that no later run +// can start; it is said, not killed. +const RunLimit = 2 * time.Hour + +// systemdTime is how systemctl shows a timestamp, in the machine's local time. +const systemdTime = "Mon 2006-01-02 15:04:05 MST" + // UpgradeHealth judges the last weekly upgrade from its service: unhealthy when it failed, naming the exit // and the last error the journal holds; healthy while it runs, after it passed, and before it ever ran. A // unit that cannot be read is unhealthy: failure is loud. func (m *Machine) UpgradeHealth() Health { - p, err := m.unitProps(WeeklyUnit, "LoadState", "ActiveState", "Result", "ExecMainStatus", "ExecMainExitTimestamp") + p, err := m.unitProps(WeeklyUnit, "LoadState", "ActiveState", "Result", "ExecMainStatus", "ExecMainExitTimestamp", "ExecMainStartTimestamp") if err != nil { return Health{Why: "the weekly upgrade's service could not be read: " + err.Error()} } @@ -34,7 +44,7 @@ func (m *Machine) UpgradeHealth() Health { case p["LoadState"] == "not-found": return Health{Healthy: true, Why: "the weekly upgrade's service is not placed yet; no upgrade has run"} case p["ActiveState"] == "activating" || p["ActiveState"] == "active": - return Health{Healthy: true, Why: "the weekly upgrade is running"} + return m.runningHealth(p["ExecMainStartTimestamp"]) case p["ActiveState"] != "failed" && p["Result"] == "success": if at := p["ExecMainExitTimestamp"]; at != "" { return Health{Healthy: true, Why: "the last weekly upgrade passed (" + at + ")"} @@ -53,6 +63,25 @@ func (m *Machine) UpgradeHealth() Health { return Health{Why: why + "; the next upgrade is the next Saturday 04:00, or a hand pacman_upgrade", Found: found} } +// runningHealth judges a run in progress: healthy within RunLimit of its start, unhealthy past it, naming the +// start and the last line the journal holds. +func (m *Machine) runningHealth(started string) Health { + at, err := time.ParseInLocation(systemdTime, started, time.Local) + if err != nil { + return Health{Why: fmt.Sprintf("the weekly upgrade is running and when it started could not be read (%q)", started)} + } + if m.Now().Sub(at) <= RunLimit { + return Health{Healthy: true, Why: "the weekly upgrade is running, since " + started} + } + why := fmt.Sprintf("the weekly upgrade has been running since %s, longer than %s: it is hung, and holds pacman's database lock so no later upgrade can start", started, RunLimit) + found := []string{} + if ls := m.journal(WeeklyUnit, 1); len(ls) > 0 && !strings.HasPrefix(ls[0], "(the journal could not be read") { + why += "; its last line: " + strings.TrimSpace(ls[0]) + found = append(found, strings.TrimSpace(ls[0])) + } + return Health{Why: why, Found: found} +} + // lastError is the last line pacman marked as an error, else the last line the journal holds; a journal that // could not be read says so in one line starting with "(", which is no error to name. func lastError(journal []string) string {